Call Hangups, debugging help

WB3FFV · November 21, 2012, 11:58pm

I have a system running under Asterisk 1.8.15.1 and FPBX 2.9.0.12, and am now having some complaints of calls being dropped when people try and call in. I am told outgoing calls all seem fine, but that for some, incoming calls keep dropping. At some level I suspect the trunk provider, but wanted to post some logging output and see if anyone sees anything that looks terribly wrong.

Here is the logging snippet, I can post even more detail from call start if needed, but it looks like it runs though all the various checks, goes to ring the extension, and a matter of seconds after the phone is answered it drops, mind you this used to all be working fine:

[Nov 21 15:33:52] VERBOSE[20220] pbx.c:     -- Executing [s@macro-dial-one:37] GotoIf("SIP/bandwidth_east-00000b28", "0?usegoto,1") in new stack
[Nov 21 15:33:52] VERBOSE[20220] pbx.c:     -- Executing [s@macro-dial-one:38] GotoIf("SIP/bandwidth_east-00000b28", "1?godial") in new stack
[Nov 21 15:33:52] VERBOSE[20220] pbx.c:     -- Goto (macro-dial-one,s,42)
[Nov 21 15:33:52] VERBOSE[20220] pbx.c:     -- Executing [s@macro-dial-one:42] Dial("SIP/bandwidth_east-00000b28", "SIP/9238,25,tr") in new stack
[Nov 21 15:33:52] VERBOSE[20220] netsock2.c:   == Using SIP RTP TOS bits 184
[Nov 21 15:33:52] VERBOSE[20220] netsock2.c:   == Using SIP RTP CoS mark 5
[Nov 21 15:33:52] VERBOSE[20220] app_dial.c:     -- Called SIP/9238
[Nov 21 15:33:52] VERBOSE[20220] app_dial.c:     -- SIP/9238-00000b29 is ringing
[Nov 21 15:33:52] VERBOSE[20220] app_dial.c:     -- SIP/9238-00000b29 is ringing
[Nov 21 15:33:58] VERBOSE[20220] app_dial.c:     -- SIP/9238-00000b29 answered SIP/bandwidth_east-00000b28
[Nov 21 15:34:07] VERBOSE[20220] pbx.c:     -- Executing [h@macro-dial-one:1] Macro("SIP/bandwidth_east-00000b28", "hangupcall,") in new stack
[Nov 21 15:34:07] VERBOSE[20220] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/bandwidth_east-00000b28", "1?theend") in new stack
[Nov 21 15:34:07] VERBOSE[20220] pbx.c:     -- Goto (macro-hangupcall,s,3)
[Nov 21 15:34:07] VERBOSE[20220] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/bandwidth_east-00000b28", "") in new stack
[Nov 21 15:34:07] VERBOSE[20220] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/bandwidth_east-00000b28' in macro 'hangupcall'
[Nov 21 15:34:07] VERBOSE[20220] features.c:   == Spawn extension (macro-dial-one, h, 1) exited non-zero on 'SIP/bandwidth_east-00000b28'
[Nov 21 15:34:07] VERBOSE[20220] app_macro.c:   == Spawn extension (macro-dial-one, s, 42) exited non-zero on 'SIP/bandwidth_east-00000b28' in macro 'dial-one'
[Nov 21 15:34:07] VERBOSE[20220] app_macro.c:   == Spawn extension (macro-exten-vm, s, 14) exited non-zero on 'SIP/bandwidth_east-00000b28' in macro 'exten-vm'
[Nov 21 15:34:07] VERBOSE[20220] pbx.c:   == Spawn extension (from-did-direct, 9238, 2) exited non-zero on 'SIP/bandwidth_east-00000b28'

Any ideas??

dicko · November 22, 2012, 12:04am

You probably need to turn SIP debugging on and try over.

sip set debug peer 9238

WB3FFV · November 23, 2012, 9:12pm

I did enable SIP debugging coming in from the bandwidth trunk, and here is some more detailed output. I would almost say it’s a NAT issue, but this ONLY seems to affect incoming calls from Verizon in general, maybe coincidence who knows. This system get many hundreds of call during the day, but only a couple incoming callers, and they all say they are using Verizon, get dropped shortly after the start of the call, so why I am miffed.

The one line that has me wondering is this:

chan_sip.c: Scheduling destruction of SIP dialog ‘[email protected]’ in 6400 ms (Method: BYE)

Is that the remote end dropping the call, or are we dropping the call locally?

Here is the more complete debugging, I would for sure appreciate any input:

[Nov 23 15:43:13] VERBOSE[5127] chan_sip.c: 
<--- SIP read from UDP:216.82.224.202:5060 --->
ACK sip:[email protected]: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:[email protected];isup-oli=0>;tag=gK0e4bc97f
To: <sip:[email protected]>;tag=as6974aee7
Call-ID: [email protected]
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:[email protected]: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:[email protected];isup-oli=0>;tag=gK0e4bc97f
To: <sip:[email protected]>;tag=as6974aee7
Call-ID: [email protected]
CSeq: 11347 INVITE
Max-Forwards: 68
Contact: <sip:[email protected]: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=5060
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:[email protected];isup-oli=0>;tag=gK0e4bc97f
To: <sip:[email protected]>;tag=as6974aee7
Call-ID: [email protected]
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:[email protected]: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=5060
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:[email protected];isup-oli=0>;tag=gK0e4bc97f
To: <sip:[email protected]>;tag=as6974aee7
Call-ID: [email protected]
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:[email protected]: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=5060
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:[email protected];isup-oli=0>;tag=gK0e4bc97f
To: <sip:[email protected]>;tag=as6974aee7
Call-ID: [email protected]
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:[email protected]: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=5060
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:[email protected];isup-oli=0>;tag=gK0e4bc97f
To: <sip:[email protected]>;tag=as6974aee7
Call-ID: [email protected]
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:[email protected]: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:[email protected]: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:[email protected];isup-oli=0>;tag=gK0b66d829
To: <sip:[email protected]>;tag=as0850c6db
Call-ID: [email protected]
CSeq: 297 BYE
Record-Route: <sip:67.231.8.93;lr=on;ftag=gK0e4bc97f>
From: <sip:[email protected];isup-oli=0>;tag=gK0e4bc97f
To: <sip:[email protected]>;tag=as6974aee7
Call-ID: [email protected]
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:[email protected]: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:[email protected]: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:[email protected];isup-oli=0>;tag=gK0b66d829
To: <sip:[email protected]>;tag=as0850c6db
Call-ID: [email protected]
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 '[email protected]' 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=5060
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:[email protected];isup-oli=0>;tag=gK0b66d829
To: <sip:[email protected]>;tag=as0850c6db
Call-ID: [email protected]
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@macro-dial-one:1] Macro("SIP/bandwidth_east-000001a4", "hangupcall,") in new stack
[Nov 23 15:43:13] VERBOSE[26556] pbx.c:     -- Executing [s@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@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@macro-dial-one:1] Macro("Local/9244@from-internal-d32c;2", "hangupcall,") in new stack
[Nov 23 15:43:13] VERBOSE[26558] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("Local/9244@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@macro-hangupcall:3] Hangup("Local/9244@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@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@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@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@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@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