Jamin W. Collins
2006-Sep-08 07:04 UTC
[asterisk-users] Tracking the source of a disconnect?
I have an asterisk box configured to perform media translation (TDM <-> SIP). With this configuration, calls are essentially only passing through the asterisk box. Thus, I would think that a disconnect request should be received from one end of the call (SIP or TDM) into the asterisk box as an end of the call. However, periodically, I've been getting reports from users of being disconnected in mid-conversation. I've checked the system's logs for any indication of problems and they all appear clean. Eventually, I enabled both PRI and SIP debugging in an effort to track down the location of these disconnects. At this time it appears that the asterisk is initiating a disconnect of both the PRI and the SIP channel (see the log snippet below). However, there doesn't appear to be any indication of why the asterisk is deciding to terminate the calls. I've included a entry from the logs just prior to and following the hangup block to provide some reference, as you can see the logs show no events for about 16 seconds prior to the hangup. The IP addresses and telephone numbers in the provided log snippet have been altered, but nothing more. Any ideas on how to locate the cause or initiator of the disconnect would be most appreciated. Sep 8 08:50:39 VERBOSE[14047] logger.c: Destroying call '49c52bf870e0f4754d45449a7adc2caf@4.3.2.1' Sep 8 08:50:55 VERBOSE[31079] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Active, peerstate Connect Request Sep 8 08:50:55 VERBOSE[31079] logger.c: > Protocol Discriminator: Q.931 (8) len=9 Sep 8 08:50:55 VERBOSE[31079] logger.c: > Call Ref: len= 2 (reference 529/0x211) (Originator) Sep 8 08:50:55 VERBOSE[31079] logger.c: > Message type: DISCONNECT (69) Sep 8 08:50:55 VERBOSE[31079] logger.c: > [Sep 8 08:50:55 VERBOSE[31079] logger.c: > [08Sep 8 08:50:55 VERBOSE[31079] logger.c: > [08 02Sep 8 08:50:55 VERBOSE[31079] logger.c: > [08 02 81Sep 8 08:50:55 VERBO SE[31079] logger.c: > [08 02 81 90Sep 8 08:50:55 VERBOSE[31079] logger.c: > [08 02 81 90] Sep 8 08:50:55 VERBOSE[31079] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) Sep 8 08:50:55 VERBOSE[31079] logger.c: > Ext: 1 Cause: Unknown (16), class = Normal Event (1) ] Sep 8 08:50:55 VERBOSE[31079] logger.c: -- Hungup 'Zap/1-1' Sep 8 08:50:55 VERBOSE[31079] logger.c: == Spawn extension (outbound, 15551212121, 1) exited non-zero on 'SIP/webacd.net-081ac408' Sep 8 08:50:55 VERBOSE[31079] logger.c: set_destination: Parsing <sip:123-4567@1.2.3.4> for address/port to send to Sep 8 08:50:55 VERBOSE[31079] logger.c: set_destination: set destination to 1.2.3.4, port 5060 Sep 8 08:50:55 VERBOSE[31079] logger.c: Reliably Transmitting (no NAT) to 1.2.3.4:5060: BYE sip:123-4567@1.2.3.4 SIP/2.0 Via: SIP/2.0/UDP 4.3.2.1:5060;branch=z9hG4bK60a2b672;rport From: <sip:15551212121@4.3.2.1:5060>;tag=as40f443a0 To: <sip:123-4567@webacd.net>;tag=9961 Contact: <sip:15551212121@4.3.2.1> Call-ID: 40db4f263a3153cd85633efd509a1179@1.2.3.4 CSeq: 102 BYE User-Agent: Asterisk Max-Forwards: 70 Content-Length: 0 --- Sep 8 08:50:55 VERBOSE[14047] logger.c: <-- SIP read from 1.2.3.4:5060: SIP/2.0 200 OK To: <sip:123-4567@webacd.net>;tag=9961 From: <sip:15551212121@4.3.2.1:5060>;tag=as40f443a0 Via: SIP/2.0/UDP 4.3.2.1:5060;branch=z9hG4bK60a2b672;rport CSeq: 102 BYE Call-ID: 40db4f263a3153cd85633efd509a1179@1.2.3.4 Contact: <sip:123-4567@1.2.3.4> User-Agent: ININ/2.400.10.10609 ININCrn: 1001654588 Content-Length: 0 Sep 8 08:50:55 VERBOSE[14047] logger.c: --- (10 headers 0 lines)Sep 8 08:50:55 VERBOSE[14047] logger.c: --- (10 headers 0 lines)--- Sep 8 08:50:55 VERBOSE[14047] logger.c: Destroying call '40db4f263a3153cd85633efd509a1179@1.2.3.4' Sep 8 08:50:55 VERBOSE[14054] logger.c: < Protocol Discriminator: Q.931 (8) len=5 Sep 8 08:50:55 VERBOSE[14054] logger.c: < Call Ref: len= 2 (reference 529/0x211) (Terminator) Sep 8 08:50:55 VERBOSE[14054] logger.c: < Message type: RELEASE (77) Sep 8 08:50:55 VERBOSE[14054] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Release Request Sep 8 08:50:55 VERBOSE[14054] logger.c: > Protocol Discriminator: Q.931 (8) len=9 Sep 8 08:50:55 VERBOSE[14054] logger.c: > Call Ref: len= 2 (reference 529/0x211) (Originator) Sep 8 08:50:55 VERBOSE[14054] logger.c: > Message type: RELEASE COMPLETE (90) Sep 8 08:50:55 VERBOSE[14054] logger.c: > [Sep 8 08:50:55 VERBOSE[14054] logger.c: > [08Sep 8 08:50:55 VERBOSE[14054] logger.c: > [08 02Sep 8 08:50:55 VERBOSE[14054] logger.c: > [08 02 81Sep 8 08:50:55 VERBO SE[14054] logger.c: > [08 02 81 90Sep 8 08:50:55 VERBOSE[14054] logger.c: > [08 02 81 90] Sep 8 08:50:55 VERBOSE[14054] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) Sep 8 08:50:55 VERBOSE[14054] logger.c: > Ext: 1 Cause: Unknown (16), class = Normal Event (1) ] Sep 8 08:50:55 VERBOSE[14054] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null Sep 8 08:50:55 VERBOSE[14054] logger.c: NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null Sep 8 08:51:39 VERBOSE[14047] logger.c: 12 headers, 0 lines -- Jamin W. Collins
Tony Mountifield
2006-Sep-08 08:15 UTC
[asterisk-users] Re: Tracking the source of a disconnect?
In article <4501787F.4070802@asgardsrealm.net>, Jamin W. Collins <jcollins@asgardsrealm.net> wrote:> I have an asterisk box configured to perform media translation (TDM <-> > SIP). With this configuration, calls are essentially only passing > through the asterisk box. Thus, I would think that a disconnect request > should be received from one end of the call (SIP or TDM) into the > asterisk box as an end of the call. > > However, periodically, I've been getting reports from users of being > disconnected in mid-conversation. I've checked the system's logs for > any indication of problems and they all appear clean. Eventually, I > enabled both PRI and SIP debugging in an effort to track down the > location of these disconnects. At this time it appears that the > asterisk is initiating a disconnect of both the PRI and the SIP channel > (see the log snippet below). However, there doesn't appear to be any > indication of why the asterisk is deciding to terminate the calls. > > [...snip...]It looks like the PRI connection is going down first, and when that channel exits, it causes the SIP channel to be hung up. So concentrate on the PRI. Try enabling intense PRI debugging "pri intense debug span N". You may want to direct the PRI debugging to a file with "pri set debug file filename". It's not clear from the log you posted whether q931_hangup() was called because of a Q.931 message Asterisk received, or just because it decided to. Hopefully, the intense debug would make that clear. Cheers Tony -- Tony Mountifield Work: tony@softins.co.uk - http://www.softins.co.uk Play: tony@mountifield.org - http://tony.mountifield.org
Jamin W. Collins
2006-Sep-14 10:32 UTC
[asterisk-users] Tracking the source of a disconnect?
Jamin W. Collins wrote:> periodically, I've been getting reports from users of being > disconnected in mid-conversation. I've checked the system's logs for > any indication of problems and they all appear clean. Eventually, I > enabled both PRI and SIP debugging in an effort to track down the > location of these disconnects. At this time it appears that the > asterisk is initiating a disconnect of both the PRI and the SIP > channel (see the log snippet below). However, there doesn't appear > to be any indication of why the asterisk is deciding to terminate the > calls.This problem has continued even after an upgrade to Asterisk 1.2.12, Zaptel 1.2.9, and libpri 1.2.3. All of the debugging so far (SIP and intense PRI) have only confirmed that the Asterisk box is the initiator of the disconnect request. In all cases I've reviewed so far, the Asterisk system initiates a disconnect on the PRI channel followed by sending a BYE request to the SIP party. The system has currently been taken out of service due to the frequency of calls being randomly terminated. Any suggestions or ideas on how to isolate the cause/source of the disconnects would be most appreciated. Motherboard: H8SSL-i rev: 1.02[1] Memory: 1 Gig DDR400 (2x 512M) T1 Card: TE110P rev: --B [1]-http://www.supermicro.com/Aplus/motherboard/Opteron/HT1000/H8SSL-i.cfm -- Jamin W. Collins