[asterisk-users] Tracking the source of a disconnect?

[Jamin W. Collins]

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 at 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 at 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 at 1.2.3.4 SIP/2.0
Via: SIP/2.0/UDP 4.3.2.1:5060;branch=z9hG4bK60a2b672;rport
From: <sip:15551212121 at 4.3.2.1:5060>;tag=as40f443a0
To: <sip:123-4567 at webacd.net>;tag=9961
Contact: <sip:15551212121 at 4.3.2.1>
Call-ID: 40db4f263a3153cd85633efd509a1179 at 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 at webacd.net>;tag=9961
From: <sip:15551212121 at 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 at 1.2.3.4
Contact: <sip:123-4567 at 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 at 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