ppslim Posted July 18, 2014 Report Posted July 18, 2014 I have been working for quite some time (6+ months) perfectly fine with two trunks setup. Both are SIP Registered, one is my own personal account and the second is a SIP account supplied by my employer. Both are for inbound and outbound terminated calls. Until the last few weeks, everything has been absolutely fine. No problems at all, with the majority of my calls routed via my work PBX using the dialplan. My personal trunk is mostly for inbound, but I do route freephone calls through it as well as calls made with a prefix (RRT to my employers PBX means I can reduce jitter if I do this selectively). Inbound calls route to my mobile via the Snomone and always use my employers PBX. Over the last few weeks, I have noticed that the calls suddenly do not terminate correctly. I thought it has been the callers. However, I have now started to see the issue when making calls from my Snom 360 directly attached to the LAN the Snomone is on. The Snomone is behind a NAT router and there have been no physical or configuration changes in the LAN, the Snomone or at my ISP (cough, I contract for them). Any and all calls via my private trunk are fine. Due to the limited / simple setup, I completely tarted from scratch and the problem persists. So after some logging and digging, I now know the following. My employers PBX will accept the REGISTER and authenticate me successfully (as far as I can see). However, when the Snomone issues an INVITE, it gets a 401 with relevant digest payload, yet continues to return 401 when the Snomone returns the auth payload with the relevant challenge response. I can't for any reason seem to figure out what may be causing this problem. My employers PBX is Asterisk using Freepbx. The logs there don't show unauthorised, but do return a message along the lines that a retransmit didn't take place in a timely way, suggesting this timed out after 6 seconds or so. It's as if the PBX is expecting the INVITE to be issued three times. One to generate the initial challenge, then the correct response and then a further response again. Included is a SIP trace of the events from the log. IP's and domains and numbers have been changed. 2014/7/18 13:16:13 Tx: udp:10.200.1.89:5060 (810 bytes) INVITE sip:07777777777@ny-pbx.domain.com;user=phone SIP/2.0 v: SIP/2.0/UDP 192.168.0.194:5060;branch=z9hG4bK-71153e27db7dacc38d2ccb1678683c44;rport f: "633" <sip:633@ny-pbx.domain.com>;tag=2083537615 t: <sip:07777777777@ny-pbx.domain.com> i: bfed76ba@pbx CSeq: 10360 INVITE Max-Forwards: 70 m: <sip:633@192.168.0.194:5060;transport=udp> Supported: 100rel, replaces, norefersub Allow-Events: refer Allow: INVITE, ACK, CANCEL, BYE, REFER, PRACK, INFO, UPDATE Accept: application/sdp User-Agent: Vodia-PBX/5.1.3 c: application/sdp l: 252 v=0 o=- 1320870782 1320870782 IN IP4 192.168.0.194 s=- c=IN IP4 192.168.0.194 t=0 0 m=audio 60838 RTP/AVP 9 8 0 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv 2014/7/18 13:16:13 Rx: udp:10.200.1.89:5060 (545 bytes) SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.0.194:5060;branch=z9hG4bK-71153e27db7dacc38d2ccb1678683c44;received=10.2.2.54;rport=5060 From: "633" <sip:633@ny-pbx.domain.com>;tag=2083537615 To: <sip:07777777777@ny-pbx.domain.com>;tag=as510dddc6 Call-ID: bfed76ba@pbx CSeq: 10360 INVITE Server: FPBX-2.10.1(1.8.10.1) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7778098d" Content-Length: 0 2014/7/18 13:16:13 Tx: udp:10.200.1.89:5060 (321 bytes) ACK sip:07777777777@ny-pbx.domain.com;user=phone SIP/2.0 v: SIP/2.0/UDP 192.168.0.194:5060;branch=z9hG4bK-71153e27db7dacc38d2ccb1678683c44;rport f: "633" <sip:633@ny-pbx.domain.com>;tag=2083537615 t: <sip:07777777777@ny-pbx.domain.com>;tag=as510dddc6 i: bfed76ba@pbx CSeq: 10360 ACK Max-Forwards: 70 l: 0 2014/7/18 13:16:13 Tx: udp:10.200.1.89:5060 (993 bytes) INVITE sip:07777777777@ny-pbx.domain.com;user=phone SIP/2.0 v: SIP/2.0/UDP 192.168.0.194:5060;branch=z9hG4bK-4093e939ed9c9d85db98d63d4bf1b81e;rport f: "633" <sip:633@ny-pbx.domain.com>;tag=2083537615 t: <sip:07777777777@ny-pbx.domain.com> i: bfed76ba@pbx CSeq: 10361 INVITE Max-Forwards: 70 m: <sip:633@192.168.0.194:5060;transport=udp> Supported: 100rel, replaces, norefersub Allow-Events: refer Allow: INVITE, ACK, CANCEL, BYE, REFER, PRACK, INFO, UPDATE Accept: application/sdp User-Agent: Vodia-PBX/5.1.3 Authorization: Digest realm="asterisk",nonce="7778098d",response="a0cce39a773b1a7eee07d7e1eb44d6dc",username="633",uri="sip:07777777777@ny-pbx.domain.com;user=phone",algorithm=MD5 c: application/sdp l: 252 v=0 o=- 1320870782 1320870782 IN IP4 192.168.0.194 s=- c=IN IP4 192.168.0.194 t=0 0 m=audio 60838 RTP/AVP 9 8 0 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv 2014/7/18 13:16:14 Rx: udp:10.200.1.89:5060 (545 bytes) SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.0.194:5060;branch=z9hG4bK-71153e27db7dacc38d2ccb1678683c44;received=10.2.2.54;rport=5060 From: "633" <sip:633@ny-pbx.domain.com>;tag=2083537615 To: <sip:07777777777@ny-pbx.domain.com>;tag=as510dddc6 Call-ID: bfed76ba@pbx CSeq: 10360 INVITE Server: FPBX-2.10.1(1.8.10.1) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7778098d" Content-Length: 0 2014/7/18 13:16:14 Tx: udp:10.200.1.89:5060 (368 bytes) ACK sip:07777777777@ny-pbx.domain.com;user=phone SIP/2.0 v: SIP/2.0/UDP 192.168.0.194:5060;branch=z9hG4bK-4093e939ed9c9d85db98d63d4bf1b81e;rport f: "633" <sip:633@ny-pbx.domain.com>;tag=2083537615 t: <sip:07777777777@ny-pbx.domain.com>;tag=as510dddc6 i: bfed76ba@pbx CSeq: 10361 ACK Max-Forwards: 70 m: <sip:633@192.168.0.194:5060;transport=udp> l: 0 I understand how Digest auth works in HTTP and I have had a go are looking at the RFCs, but I cannot calculate the response to the challenge manually, thus I have been unable to calculate if or not it is a genuine unauthorised, or Snomone is doing something silly. However, it's only this trunk, as again, my personal one is fine, though this uses a 407 Proxy authentication required. Are there any pointers on working out what may or may not be going on? Afterall, REGISTER is fine, but INVITE is not, so the shared secret should not be the cause. Quote
Vodia support Posted July 19, 2014 Report Posted July 19, 2014 Looks like snomONE is doing its Job, for testing purpose can you re-create the trunk and assign a different password on the freepbx. in case of typos. Also if you upgrade to version 5.2.3 you can capture a PCAP from the trunk level. http://wiki.snomone.com/index.php?title=Trunk_PCAP_Generation Quote
ppslim Posted July 19, 2014 Author Report Posted July 19, 2014 Hmm, I had written a long response to that, then spotted a key point of your reply 5.2.3. I thought it was a typo as I am on 5.1.3. I even double checked the wiki. So it would have it, I didn't know that there was a 5.2.x at all!!! Maybe something to put on the wiki. I'm off to try this before I send you the large mass of text I just deleted Quote
ppslim Posted July 19, 2014 Author Report Posted July 19, 2014 Well, that has not helped any. I had already enabled PCAP, which is my preferred analysis method. I just didn't have wireshark on the machine I raised the post on. The captures do store details about registration though, so I cannot conclusivly prove what is hapening there. However the trunk screen does show registered. I did change the password at the remote side and this reflected as registration failed in the Snomone. Then updating it it went back to registered. So I am confident it is right. Following the logs at the remote end, I know it is not a password issue either, as it would show it (we already see these for other extensions, namely intrusion attempts). However, I have just noted the following. When a call is made over this trunk, I see the following. >INVITE <401 >ACK >INVITE (with auth) <401 >ACK However the remote PBX places the call anyway over it's own trunk. e.g. dialing my mobile from my Snom 360 via the Snom one, places the SIP flow above. The remote PBX despite returning 401 places the call anyway to my mobile, which drops when answered because the call flow is never completed. The Asterisk logs do show the following though: [2014-07-19 16:10:01] WARNING[21715] chan_sip.c: ignoring 'video' media offer because port number is zero [2014-07-19 16:10:12] WARNING[21715] chan_sip.c: Retransmission timeout reached on transmission d28e1353@pbx for seqno 26642 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+RetransmissionsPacket timed out after 6976ms with no response[2014-07-19 16:10:12] WARNING[21715] chan_sip.c: Hanging up call d28e1353@pbx - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions). This call ID matches the call attempt from the Snomone logs. Doing some careful timing events, the 6976ms timeout is hey presto, 6 seconds after the Snomone receives the second 401. Yesterday I was able to provision a Aastra phone on the PBX in the office to this extension to check that would work. However, this was on the office LAN were 30+ other phones work fine, whilst my Snomone is remote. It just doesn't seem logical. Unfortunately, I cannot packet capture from the office PBX, so I cannot see the call flow from the Aastra to the PBX and then compare it to my Snomone captures. I do hope to try an bring my provisioned phone to here though, and see what happens when it's on the switch port next to the Snomone. Quote
Vodia PBX Posted July 22, 2014 Report Posted July 22, 2014 It is indeed looking very strange. I would definitively run a PCAP (tshark) on the Asterisk system to see "their point of view". Maybe there is a firewall in between slowing down the INVITE. If the Asterisk still believes that there was a timeout, then things get really wacky. Especially because the REGISTER seems to work as expected, and just the INVITE makes problems. But I think the retransmission timeout does not mean that the request was too slow. I read this as that the retransmission did not make it at all. You see by the sequence number that the 2nd INVITE (CSeq increased by one) probably does not hit the Asterisk system at all. You will see that in the PCAP on the Asterisk system. So why would the 2nd INVITE get lost and the first one not? The first INVITE is 810 bytes and the 2nd one is 993. There is a reason why we put those numbers into the log: UDP Fragmentation. in the LAN it is usually around 1500 bytes; but in your case it might be lower and just between those two packet lengths. But as it looks to me, I would try to follow the path from the Vodia PBX to the Asterisk PBX and try to isolate where the 2nd packet gets lost. Quote
ppslim Posted July 22, 2014 Author Report Posted July 22, 2014 Oooh, I had not spotted the second 401 was in sequence to the original INVITE, not the 2nd. I forgot SIP may send multiple signals due to use of UDP. Fragmentation is unlikely, but I am exploring this regardless, including use of a tunnel source & destination side to negate any fragmentation at the sacrifice of latency (yet if latency is the cause, I certainly have a problem that this ain't going to help with). I am also going to put some codec limits on the trunk, as well as a few other tweaks in a bid to limit request size and rule this out further. Quote
Recommended Posts
Join the conversation
You can post now and register later. If you have an account, sign in now to post with your account.
Note: Your post will require moderator approval before it will be visible.