[asterisk-users] SIP Debugging Information..

Sat Nov 24 14:19:10 CST 2012

 I did a little googling, but didn't seem to find anything specific to
answer the question.   I am trying to debug some calls on an Asterisk system
(AsteriskNow) that are dropping, and when the general logs didn't nail
anything I turned on SIP Debugging on the trunk to the provider.
Basically the complaint is that when some call in, regardless of if the call
is answered, or if Vmail answers it, it drops the calls in a matter of
seconds.   The strange thing is, that the system processes many hundreds of
calls daily, but only a couple specific incoming callers are seeing the
drops.  I would have thought a NAT issue, but why does this only affect a
specific group of incoming callers, the rest go about their business just
fine.  I think thinking bandwidth.com is mucking something up, but again I
have no specific proof one way or another, so why the debugging.

 When one of the problem callers is dropped, in the SIP debugging I see:

  chan_sip.c: Scheduling destruction of SIP dialog
'285991942_79966325 at 192.168.27.72' in 6400 ms (Method: BYE)

Is this the remote end (ie bandwidth.com) dropping the call, or is the local
Asterisk server dropping the call?

 For any that care to look at all the gory details, here is a chunk of the
debugging output:

[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- SIP read from UDP:216.82.224.202:5060 --->
ACK sip:4104159233 at 10.98.4.36:5060 SIP/2.0
Record-Route: <sip:216.82.224.202;lr;ftag=gK0e4bc97f>
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKebf3.453cc5a5.2
Via: SIP/2.0/UDP 67.231.8.93;branch=z9hG4bKebf3.315d4e14.3
Via: SIP/2.0/UDP 192.168.37.72:5060;branch=z9hG4bK0eB7f5f0b80116aa493
From: <sip:2159470824 at 192.168.37.72;isup-oli=0>;tag=gK0e4bc97f
To: <sip:+14104159233 at 67.231.8.93>;tag=as6974aee7
Call-ID: 353260172_48597606 at 192.168.37.72
CSeq: 11346 ACK
Max-Forwards: 68
Content-Length: 0

<------------->
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: --- (12 headers 0 lines) ---
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- SIP read from UDP:216.82.224.202:5060 --->
INVITE sip:4104159233 at 10.98.4.36:5060 SIP/2.0
Record-Route: <sip:216.82.224.202;lr;ftag=gK0e4bc97f>
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKfbf3.9d9b1065.0
Via: SIP/2.0/UDP 67.231.8.93;branch=z9hG4bKfbf3.c159a6a.0
Via: SIP/2.0/UDP 192.168.37.72:5060;branch=z9hG4bK0eB7f601a4d116aa493
From: <sip:2159470824 at 192.168.37.72;isup-oli=0>;tag=gK0e4bc97f
To: <sip:+14104159233 at 67.231.8.93>;tag=as6974aee7
Call-ID: 353260172_48597606 at 192.168.37.72
CSeq: 11347 INVITE
Max-Forwards: 68
Contact: <sip:+12159470824 at 192.168.37.72:5060>
Content-Length: 235
Content-Disposition: session; handling=required
Content-Type: application/sdp

v=0
o=Sonus_UAC 22153 5058 IN IP4 192.168.37.72
s=SIP Media Capabilities
c=IN IP4 67.231.8.102
t=0 0
m=audio 6576 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=maxptime:20
<------------->
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: --- (15 headers 11 lines) ---
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Sending to 216.82.224.202:5060
(NAT)
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Found RTP audio format 0
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Found RTP audio format 101
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Found audio description format
PCMU for ID 0
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Found audio description format
telephone-event for ID 101
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Capabilities: us - 0x104
(ulaw|g729), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing),
combined - 0x4 (ulaw)
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Non-codec capabilities (dtmf):
us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1
(telephone-event|)
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Peer audio RTP is at port
67.231.8.102:6576
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- Transmitting (NAT) to 216.82.224.202:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
216.82.224.202;branch=z9hG4bKfbf3.9d9b1065.0;received=216.82.224.202;rport=5
060
Via: SIP/2.0/UDP 67.231.8.93;branch=z9hG4bKfbf3.c159a6a.0
Via: SIP/2.0/UDP 192.168.37.72:5060;branch=z9hG4bK0eB7f601a4d116aa493
Record-Route: <sip:216.82.224.202;lr;ftag=gK0e4bc97f>
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
From: <sip:2159470824 at 192.168.37.72;isup-oli=0>;tag=gK0e4bc97f
To: <sip:+14104159233 at 67.231.8.93>;tag=as6974aee7
Call-ID: 353260172_48597606 at 192.168.37.72
CSeq: 11347 INVITE
Server: FPBX-2.9.0(1.8.15.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH
Supported: replaces
Contact: <sip:4104159233 at 10.98.4.36:5060>
Content-Length: 0

<------------>
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Audio is at 11444
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Adding non-codec 0x1
(telephone-event) to SDP
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- Reliably Transmitting (NAT) to 216.82.224.202:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
216.82.224.202;branch=z9hG4bKfbf3.9d9b1065.0;received=216.82.224.202;rport=5
060
Via: SIP/2.0/UDP 67.231.8.93;branch=z9hG4bKfbf3.c159a6a.0
Via: SIP/2.0/UDP 192.168.37.72:5060;branch=z9hG4bK0eB7f601a4d116aa493
Record-Route: <sip:216.82.224.202;lr;ftag=gK0e4bc97f>
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
From: <sip:2159470824 at 192.168.37.72;isup-oli=0>;tag=gK0e4bc97f
To: <sip:+14104159233 at 67.231.8.93>;tag=as6974aee7
Call-ID: 353260172_48597606 at 192.168.37.72
CSeq: 11347 INVITE
Server: FPBX-2.9.0(1.8.15.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH
Supported: replaces
Contact: <sip:4104159233 at 10.98.4.36:5060>
Content-Type: application/sdp
Content-Length: 233

v=0
o=root 1660074055 1660074056 IN IP4 10.98.4.36
s=Asterisk PBX 1.8.15.1
c=IN IP4 10.98.4.36
t=0 0
m=audio 11444 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Retransmitting #1 (NAT) to
216.82.224.202:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
216.82.224.202;branch=z9hG4bKfbf3.9d9b1065.0;received=216.82.224.202;rport=5
060
Via: SIP/2.0/UDP 67.231.8.93;branch=z9hG4bKfbf3.c159a6a.0
Via: SIP/2.0/UDP 192.168.37.72:5060;branch=z9hG4bK0eB7f601a4d116aa493
Record-Route: <sip:216.82.224.202;lr;ftag=gK0e4bc97f>
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
From: <sip:2159470824 at 192.168.37.72;isup-oli=0>;tag=gK0e4bc97f
To: <sip:+14104159233 at 67.231.8.93>;tag=as6974aee7
Call-ID: 353260172_48597606 at 192.168.37.72
CSeq: 11347 INVITE
Server: FPBX-2.9.0(1.8.15.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH
Supported: replaces
Contact: <sip:4104159233 at 10.98.4.36:5060>
Content-Type: application/sdp
Content-Length: 233

v=0
o=root 1660074055 1660074056 IN IP4 10.98.4.36
s=Asterisk PBX 1.8.15.1
c=IN IP4 10.98.4.36
t=0 0
m=audio 11444 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Retransmitting #2 (NAT) to
216.82.224.202:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP
216.82.224.202;branch=z9hG4bKfbf3.9d9b1065.0;received=216.82.224.202;rport=5
060
Via: SIP/2.0/UDP 67.231.8.93;branch=z9hG4bKfbf3.c159a6a.0
Via: SIP/2.0/UDP 192.168.37.72:5060;branch=z9hG4bK0eB7f601a4d116aa493
Record-Route: <sip:216.82.224.202;lr;ftag=gK0e4bc97f>
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
From: <sip:2159470824 at 192.168.37.72;isup-oli=0>;tag=gK0e4bc97f
To: <sip:+14104159233 at 67.231.8.93>;tag=as6974aee7
Call-ID: 353260172_48597606 at 192.168.37.72
CSeq: 11347 INVITE
Server: FPBX-2.9.0(1.8.15.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH
Supported: replaces
Contact: <sip:4104159233 at 10.98.4.36:5060>
Content-Type: application/sdp
Content-Length: 233

v=0
o=root 1660074055 1660074056 IN IP4 10.98.4.36
s=Asterisk PBX 1.8.15.1
c=IN IP4 10.98.4.36
t=0 0
m=audio 11444 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- SIP read from UDP:216.82.224.202:5060 --->
BYE sip:4104159270 at 10.98.4.36:5060 SIP/2.0
Record-Route: <sip:216.82.224.202;lr;ftag=gK0b66d829>
Record-Route: <sip:67.231.4.93;lr=on;ftag=gK0b66d829>
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKe902.53bde7e.0
Via: SIP/2.0/UDP 67.231.4.93;branch=z9hG4bKe902.32697e93.0
Via: SIP/2.0/UDP 192.168.27.72:5060;branch=z9hG4bK0bBac8c2c3cb90659df
From: <sip:7173381800 at 192.168.27.72;isup-oli=0>;tag=gK0b66d829
To: <sip:+14104159270 at 67.231.4.93>;tag=as0850c6db
Call-ID: 285991942_79966325 at 192.168.27.72
CSeq: 297 BYE
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
From: <sip:2159470824 at 192.168.37.72;isup-oli=0>;tag=gK0e4bc97f
To: <sip:+14104159233 at 67.231.8.93>;tag=as6974aee7
Call-ID: 353260172_48597606 at 192.168.37.72
CSeq: 11347 INVITE
Server: FPBX-2.9.0(1.8.15.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH
Supported: replaces
Contact: <sip:4104159233 at 10.98.4.36:5060>
Content-Type: application/sdp
Content-Length: 233

v=0
o=root 1660074055 1660074056 IN IP4 10.98.4.36
s=Asterisk PBX 1.8.15.1
c=IN IP4 10.98.4.36
t=0 0
m=audio 11444 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

---
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- SIP read from UDP:216.82.224.202:5060 --->
BYE sip:4104159270 at 10.98.4.36:5060 SIP/2.0
Record-Route: <sip:216.82.224.202;lr;ftag=gK0b66d829>
Record-Route: <sip:67.231.4.93;lr=on;ftag=gK0b66d829>
Via: SIP/2.0/UDP 216.82.224.202;branch=z9hG4bKe902.53bde7e.0
Via: SIP/2.0/UDP 67.231.4.93;branch=z9hG4bKe902.32697e93.0
Via: SIP/2.0/UDP 192.168.27.72:5060;branch=z9hG4bK0bBac8c2c3cb90659df
From: <sip:7173381800 at 192.168.27.72;isup-oli=0>;tag=gK0b66d829
To: <sip:+14104159270 at 67.231.4.93>;tag=as0850c6db
Call-ID: 285991942_79966325 at 192.168.27.72
CSeq: 297 BYE
Max-Forwards: 68
Content-Length: 0

<------------->
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: --- (12 headers 0 lines) ---
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Sending to 216.82.224.202:5060
(NAT)
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: Scheduling destruction of SIP
dialog '285991942_79966325 at 192.168.27.72' in 6400 ms (Method: BYE)
[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- Transmitting (NAT) to 216.82.224.202:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
216.82.224.202;branch=z9hG4bKe902.53bde7e.0;received=216.82.224.202;rport=50
60
Via: SIP/2.0/UDP 67.231.4.93;branch=z9hG4bKe902.32697e93.0
Via: SIP/2.0/UDP 192.168.27.72:5060;branch=z9hG4bK0bBac8c2c3cb90659df
Record-Route: <sip:216.82.224.202;lr;ftag=gK0b66d829>
Record-Route: <sip:67.231.4.93;lr=on;ftag=gK0b66d829>
From: <sip:7173381800 at 192.168.27.72;isup-oli=0>;tag=gK0b66d829
To: <sip:+14104159270 at 67.231.4.93>;tag=as0850c6db
Call-ID: 285991942_79966325 at 192.168.27.72
CSeq: 297 BYE
Server: FPBX-2.9.0(1.8.15.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH
Supported: replaces
Content-Length: 0

<------------>
[Nov 23 15:43:13] VERBOSE[26556] pbx.c:     -- Executing
[h at macro-dial-one:1] Macro("SIP/bandwidth_east-000001a4", "hangupcall,") in
new stack
[Nov 23 15:43:13] VERBOSE[26556] pbx.c:     -- Executing
[s at macro-hangupcall:1] GotoIf("SIP/bandwidth_east-000001a4", "1?theend") in
new stack
[Nov 23 15:43:13] VERBOSE[26556] pbx.c:     -- Goto (macro-hangupcall,s,3)
[Nov 23 15:43:13] VERBOSE[26556] pbx.c:     -- Executing
[s at macro-hangupcall:3] Hangup("SIP/bandwidth_east-000001a4", "") in new
stack
[Nov 23 15:43:13] VERBOSE[26556] app_macro.c:   == Spawn extension
(macro-hangupcall, s, 3) exited non-zero on 'SIP/bandwidth_east-000001a4' in
macro 'hangupcall'
[Nov 23 15:43:13] VERBOSE[26556] features.c:   == Spawn extension
(macro-dial-one, h, 1) exited non-zero on 'SIP/bandwidth_east-000001a4'
[Nov 23 15:43:13] VERBOSE[26556] app_macro.c:   == Spawn extension
(macro-dial-one, s, 42) exited non-zero on 'SIP/bandwidth_east-000001a4' in
macro 'dial-one'
[Nov 23 15:43:13] VERBOSE[26556] app_macro.c:   == Spawn extension
(macro-exten-vm, s, 14) exited non-zero on 'SIP/bandwidth_east-000001a4' in
macro 'exten-vm'
[Nov 23 15:43:13] VERBOSE[26556] pbx.c:   == Spawn extension
(from-did-direct, 9237, 2) exited non-zero on 'SIP/bandwidth_east-000001a4'
[Nov 23 15:43:13] VERBOSE[26558] pbx.c:     -- Executing
[h at macro-dial-one:1] Macro("Local/9244 at from-internal-d32c;2", "hangupcall,")
in new stack
[Nov 23 15:43:13] VERBOSE[26558] pbx.c:     -- Executing
[s at macro-hangupcall:1] GotoIf("Local/9244 at from-internal-d32c;2", "1?theend")
in new stack
[Nov 23 15:43:13] VERBOSE[26558] pbx.c:     -- Goto (macro-hangupcall,s,3)
[Nov 23 15:43:13] VERBOSE[26558] pbx.c:     -- Executing
[s at macro-hangupcall:3] Hangup("Local/9244 at from-internal-d32c;2", "") in new
stack
[Nov 23 15:43:13] VERBOSE[26558] app_macro.c:   == Spawn extension
(macro-hangupcall, s, 3) exited non-zero on
'Local/9244 at from-internal-d32c;2' in macro 'hangupcall'
[Nov 23 15:43:13] VERBOSE[26558] features.c:   == Spawn extension
(macro-dial-one, h, 1) exited non-zero on 'Local/9244 at from-internal-d32c;2'
[Nov 23 15:43:13] VERBOSE[26558] app_macro.c:   == Spawn extension
(macro-dial-one, s, 42) exited non-zero on 'Local/9244 at from-internal-d32c;2'
in macro 'dial-one'
[Nov 23 15:43:13] VERBOSE[26558] app_macro.c:   == Spawn extension
(macro-exten-vm, s, 14) exited non-zero on 'Local/9244 at from-internal-d32c;2'
in macro 'exten-vm'
[Nov 23 15:43:13] VERBOSE[26558] pbx.c:   == Spawn extension (from-internal,
9244, 2) exited non-zero on 'Local/9244 at from-internal-d32c;2'
[Nov 23 15:43:13] VERBOSE[2746] chan_sip.c:   == Extension Changed
9244[ext-local] new state Idle for Notify User 9237

For sure any help or input on tracing this all down is most appreciated...

---
Howard Leadmon