Dropping calls within the first few minutes

steve_d · January 8, 2013, 3:55pm

Hello,

My asterisk box is dropping calls after a few minutes of call time. In the case below the call was terminated at about 4 minutes. This specific call was when the user was on a conference bridge (goto meeting or similar).

I have a fiber connection to our ISP dedicated to our sip trunk, with no NAT. The server has two NIC’s, one for the trunk, and one for the local phone lan (dedicated physical network).

The phones being used are Aastra 9112i or 6730i, the call below was on a 6730i.

We also have an iAX trunk over the internet between two of our offices for over a year and a half, and have very rarely experienced a dropped call - typically these calls will go for 20-30 minutes.

I have troubleshoot’d this issue with our trunk provider and on their side error messages list: Reason: Q.850 ;cause=31 ;text=“local, RTP Broken Connection” - although not for this specific call listed below, I don’t have direct access to our providers sip team anymore.

I’ve done some captures with tcpdump - wireshark shows out of order packets in the rtp stream, typically only in one direction (phone -> pbx, but typically not pbx -> phone). I’m not sure if it is normal to experience packets out of order like this.

Any help is greatly appreciated!

[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Bridge still active.  Delaying destroy of SIP dialog '2e30222326445c670d504c8208292976@10.0.1.67:5060' Method: INVITE
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Bridge still active.  Delaying destroy of SIP dialog 'a2b872537172f874' Method: ACK
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan  8 10:05:33] DEBUG[6920] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces"
[Jan  8 10:05:33] DEBUG[6920] sip/reqresp_parser.c: Found SIP option: -replaces-
[Jan  8 10:05:33] DEBUG[6920] sip/reqresp_parser.c: Matched SIP option: replaces
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing session-level SDP o=root 1726955180 1726955182 IN IP4 173.46.30.202... UNSUPPORTED.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing session-level SDP s=Rogers SIP... UNSUPPORTED.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing session-level SDP c=IN IP4 173.46.30.202... OK.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Jan  8 10:05:33] DEBUG[6920] rtp_engine.c: Setting payload 0 based on m type on 0x41395570
[Jan  8 10:05:33] DEBUG[6920] rtp_engine.c: Setting payload 101 based on m type on 0x41395570
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Jan  8 10:05:33] DEBUG[6920] rtp_engine.c: Incorporating payload 0 on 0x41395570
[Jan  8 10:05:33] DEBUG[6920] rtp_engine.c: Incorporating payload 101 on 0x41395570
[Jan  8 10:05:33] DEBUG[6920] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1f6de198'
[Jan  8 10:05:33] DEBUG[6920] rtp_engine.c: Copying payload 0 from 0x41395570 to 0x1f6de360
[Jan  8 10:05:33] DEBUG[6920] rtp_engine.c: Copying payload 101 from 0x41395570 to 0x1f6de360
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: We have an owner, now see if we need to change this call
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: SIP/Rogers-central-0000025f: This call is UP.... 
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 173.46.30.202:5060
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Setting framing from config on incoming call
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) 
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: -- Done with adding codecs to SDP
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 173.46.30.202:5060
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Bridge still active.  Delaying destroy of SIP dialog '2e30222326445c670d504c8208292976@10.0.1.67:5060' Method: INVITE
[Jan  8 10:05:33] DEBUG[3766] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for 173.46.30.202:5060
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Stopping retransmission on '2e30222326445c670d504c8208292976@10.0.1.67:5060' of Response 102: Match Found
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Stopping retransmission on '2e30222326445c670d504c8208292976@10.0.1.67:5060' of Response 102: Match Found
[Jan  8 10:05:33] DEBUG[6920] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2e30222326445c670d504c8208292976@10.0.1.67:5060
[Jan  8 10:05:33] DEBUG[6932] manager.c: Examining event:

david55 · January 8, 2013, 3:59pm

The remote system made the decision to drop the call!

steve_d · January 8, 2013, 5:11pm

So this is the external host (my trunk provider) saying the call was hung up?

chan_sip.c: **** Received BYE (8) - Command in SIP BYE

I’m wondering if the ‘RTP broken connection’ our provider gets triggers the hang up, is there any way to troubleshoot the rtp stream and see if its my end causing the issue?

Also should I be expecting wrong timestamps and out of sequence packets when reviewing a call in wireshark?

https://dl.dropbox.com/u/21916057/Screenshot%20from%202013-01-08%2012%3A08%3A10.png

steve_d · January 8, 2013, 5:55pm

On another call that dropped out after about 3 minutes I have a packet capture:

https://dl.dropbox.com/u/21916057/Screenshot%20from%202013-01-08%2012%3A49%3A05.png

10.0.250.192 is the phone
10.0.250.2 is the pbx lan interface
10.0.1.67 is the pbx external interface
173.46.30.202 is the trunk provider’s box

Is it normal for the trunk side to send an INVITE in the middle of the call? I thought an INVITE was for the initial call request, but in this case an INVITE comes in while the call is already in progress, and then immediately a BYE is received from the trunk.

david55 · January 8, 2013, 6:07pm

Re-invites are a normal mechanism, used to change media addresses (particularly to implement “direct media”), hold and unhold calls, change connected line information, etc. Not all user agents handle re-invites well, but dropouts due to mishandling of them tend to happen within about 30 seconds.

david55 · January 8, 2013, 6:21pm

Re: RTP timing errors, Asterisk doesn’t maintain SSRC values properly, so source changes produce unannounced timestamp changes. (It sets the marker bit, but that is a mis-use of the marker bit.) Most things tolerate this. I’ve experienced temporary audio problems, but no call drops.

steve_d · January 10, 2013, 8:04pm

I still haven’t tracked down the issue yet. I have found a work around though - I purchased usb headsets and am using an IAX capable softphone (zoiper) for our reps. No dropped calls since.

I also found that it is only outbound calls that are being terminated unexpectedly on the Aastra phones - I’m suspecting there is something in particular wrong with the 9112i and the way the session is bridged to our trunk. I don’t seem to have the same issues with Aastra 6730i phones, but they are a few years newer than the 9112i’s.

I found this trunk option “ignoresdpversion=yes” in relation to SDP issues with some trunk providers in another thread, but alas it didn’t have a noticeable effect, althougth there are enough SDP listings in the log files to raise my suspicions that the issue has something to do with SDP.