Random outbound call failure issues

Get help with installing and running AsteriskNOW.

Moderators: Moderator, Support

Random outbound call failure issues

Postby sfogg » Thu Jan 08, 2015 1:15 pm

Hi all.

We've got several AsteriskNOW installations out, but one site in particular is having issues with outbound calling. At random (usually 2-5 per day) the outbound call will ring on both ends, but once the destination end picks up, the line goes 'dead' with no audio. Retrying the call will generally work immediately, and the calls are stable once fully established. There appears to be no other pattern; this affects most--if not all--the users, and seems to happen regardless of server load, network traffic, or number of active calls. .

All the users are operating Linksys SPA 942 or Cisco SPA303 handsets. No other major issues (that can't be traced back to internet issues or similar) seem to be in play.

I grabbed a debug SIP log of one of the failed calls. I've modified the log to remove user info etc: I've stripped out identifiable info and replaced with placeholders.

Near as I can tell, the call starts coming apart at the section highlighted in yellow with a fault on chan_spi.c. Based on what I can tell via Google-Fu is that this error is caused by RTP INVITE/ACK UDP packets arriving out-of-order which nukes the call.

This is the same build, same hardware, and in many cases using the same internet provider as we have at several other sites. As mentioned, this issue is totally random, and otherwise works perfectly. As such, I'm at a total loss of where to go from here to troubleshoot/repair.

I'd be pleased to offer up any non-identifiable information on request.

[log in next post]
sfogg
Newsterisk
 
Posts: 3
Joined: Thu Jan 08, 2015 10:09 am

Re: Random outbound call failure issues

Postby sfogg » Thu Jan 08, 2015 1:16 pm

For you log-geek's enjoyment:

[2015-01-08 09:07:59] VERBOSE[2240][C-00000306] netsock2.c: == Using SIP RTP TOS bits 184
[2015-01-08 09:07:59] VERBOSE[2240][C-00000306] netsock2.c: == Using SIP RTP CoS mark 5
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [Destination##@from-internal:1] Macro("SIP/102-000006e7", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/102-000006e7", "TOUCH_MONITOR=1420729679.1837") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/102-000006e7", "AMPUSER=102") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/102-000006e7", "0?report") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/102-000006e7", "1?Set(REALCALLERIDNUM=102)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/102-000006e7", "AMPUSER=102") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:6] Set("SIP/102-000006e7", "AMPUSERCIDNAME={EDNA P USERNAME}") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:7] GotoIf("SIP/102-000006e7", "0?report") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/102-000006e7", "AMPUSERCID=102") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/102-000006e7", "__DIAL_OPTIONS=Ttr") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/102-000006e7", "CALLERID(all)="{EDNA P USERNAME}" <102>") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:11] GotoIf("SIP/102-000006e7", "0?limit") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/102-000006e7", "1?Set(GROUP(concurrency_limit)=102)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/102-000006e7", "1?continue") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Goto (macro-user-callerid,s,26)
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/102-000006e7", "CALLERID(number)=102") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/102-000006e7", "CALLERID(name)={EDNA P USERNAME}") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/102-000006e7", "CDR(cnum)=102") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/102-000006e7", "CDR(cnam)={EDNA P USERNAME}") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/102-000006e7", "CHANNEL(language)=en") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [Destination##@from-internal:2] Set("SIP/102-000006e7", "MOHCLASS=default") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [Destination##@from-internal:3] Set("SIP/102-000006e7", "_NODEST=") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [Destination##@from-internal:4] Gosub("SIP/102-000006e7", "sub-record-check,s,1(out,Destination##,)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:1] Set("SIP/102-000006e7", "REC_POLICY_MODE_SAVE=") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("SIP/102-000006e7", "1?check") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Goto (sub-record-check,s,7)
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/102-000006e7", "__MON_FMT=wav") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("SIP/102-000006e7", "1?next") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Goto (sub-record-check,s,11)
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/102-000006e7", "0?Return()") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("SIP/102-000006e7", "0?Set(__REC_POLICY_MODE=)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("SIP/102-000006e7", "0?out,1") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/102-000006e7", "__REC_STATUS=INITIALIZED") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/102-000006e7", "NOW=1420729679") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/102-000006e7", "__DAY=08") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/102-000006e7", "__MONTH=01") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/102-000006e7", "__YEAR=2015") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/102-000006e7", "__TIMESTR=20150108-090759") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/102-000006e7", "__FROMEXTEN=102") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:21] Set("SIP/102-000006e7", "__CALLFILENAME=out-Destination##-102-20150108-090759-1420729679.1837") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@sub-record-check:22] Goto("SIP/102-000006e7", "out,1") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Goto (sub-record-check,out,1)
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/102-000006e7", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/102-000006e7", "0?record,1(exten,Destination##,102)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/102-000006e7", "") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [Destination##@from-internal:5] Macro("SIP/102-000006e7", "dialout-trunk,19,Destination##,,off") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/102-000006e7", "DIAL_TRUNK=19") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/102-000006e7", "0?sub-pincheck,s,1()") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/102-000006e7", "0?disabletrunk,1") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/102-000006e7", "DIAL_NUMBER=Destination##") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/102-000006e7", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/102-000006e7", "OUTBOUND_GROUP=OUT_19") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/102-000006e7", "0?nomax") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/102-000006e7", "0?chanfull") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/102-000006e7", "0?skipoutcid") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/102-000006e7", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/102-000006e7", "outbound-callerid,19") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/102-000006e7", "0?Set(CALLERPRES()=)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/102-000006e7", "0?Set(REALCALLERIDNUM=102)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/102-000006e7", "1?normcid") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Goto (macro-outbound-callerid,s,6)
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/102-000006e7", "USEROUTCID={OUTBOUND CID}) in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/102-000006e7", "EMERGENCYCID=") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/102-000006e7", "TRUNKOUTCID={OUTBOUND CID}) in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/102-000006e7", "1?trunkcid") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Goto (macro-outbound-callerid,s,14)
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/102-000006e7", "1?Set(CALLERID(all)={OUTBOUND CID}) in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/102-000006e7", "1?Set(CALLERID(all)={OUTBOUND CID}) in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/102-000006e7", "0?Set(CALLERID(all)=)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/102-000006e7", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:18] Set("SIP/102-000006e7", "CDR(outbound_cnum)={SOURCE DID## DID##}") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-outbound-callerid:19] Set("SIP/102-000006e7", "CDR(outbound_cnam)={Generic Company Corp}") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/102-000006e7", "0?sub-flp-19,s,1()") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/102-000006e7", "OUTNUM=Destination##") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/102-000006e7", "custom=SIP/{TRUNK DID##}-out") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/102-000006e7", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/102-000006e7", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/102-000006e7", "dialout-trunk-predial-hook,") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/102-000006e7", "") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/102-000006e7", "0?bypass,1") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/102-000006e7", "1?Set(CONNECTEDLINE(num,i)=Destination##)") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/102-000006e7", "1?Set(CONNECTEDLINE(name,i)=CID:{SOURCE DID##})") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/102-000006e7", "0?customtrunk") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-dialout-trunk:22] Dial("SIP/102-000006e7", "SIP/{TRUNK DID##}-out/Destination##,300,Tt") in new stack
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] netsock2.c: == Using SIP RTP TOS bits 184
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] netsock2.c: == Using SIP RTP CoS mark 5
[2015-01-08 09:07:59] VERBOSE[30973][C-00000306] app_dial.c: -- Called SIP/{TRUNK DID##}-out/Destination##
[2015-01-08 09:08:00] VERBOSE[30973][C-00000306] app_dial.c: -- SIP/{TRUNK DID##}-out-000006e8 is ringing
[2015-01-08 09:08:05] WARNING[2240][C-00000306] chan_sip.c: Invalid contact uri (missing sip: or sips:), attempting to use anyway
[2015-01-08 09:08:05] WARNING[2240][C-00000306] chan_sip.c: Invalid URI: parse_uri failed to acquire hostport

[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] app_dial.c: -- SIP/{TRUNK DID##}-out-000006e8 answered SIP/102-000006e7
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] pbx.c: -- Executing [h@macro-dialout-trunk:1] Macro("SIP/102-000006e7", "hangupcall,") in new stack
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/102-000006e7", "1?theend") in new stack
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] pbx.c: -- Goto (macro-hangupcall,s,3)
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-hangupcall:3] ExecIf("SIP/102-000006e7", "0?Set(CDR(recordingfile)=)") in new stack
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/102-000006e7", "") in new stack
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/102-000006e7' in macro 'hangupcall'
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] pbx.c: == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/102-000006e7'
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] app_macro.c: == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/102-000006e7' in macro 'dialout-trunk'
[2015-01-08 09:08:05] VERBOSE[30973][C-00000306] pbx.c: == Spawn extension (from-internal, Destination##, 5) exited non-zero on 'SIP/102-000006e7'
sfogg
Newsterisk
 
Posts: 3
Joined: Thu Jan 08, 2015 10:09 am

Re: Random outbound call failure issues

Postby david55 » Thu Jan 08, 2015 5:44 pm

Difficult to tell without sip debug enabled, but my guess is that you are being sent TEL: URIs, and this is nothing to do with arrival order.
david55
Moves Like Spencer
 
Posts: 12570
Joined: Fri Sep 26, 2008 5:03 am

Re: Random outbound call failure issues

Postby sfogg » Fri Jan 09, 2015 12:57 pm

I'll enable SIP debugging and see if I can't capture another failed call.

In the meantime, any advice would be appreciated.
sfogg
Newsterisk
 
Posts: 3
Joined: Thu Jan 08, 2015 10:09 am

Re: Random outbound call failure issues

Postby doublview » Sun Jan 18, 2015 6:43 am

How do you actuly enable sip debugging?
doublview
Newsterisk
 
Posts: 12
Joined: Tue Jan 13, 2015 4:50 am

Re: Random outbound call failure issues

Postby david55 » Sun Jan 18, 2015 7:28 am

CLI: sip set debug on

logger.conf: uncomment full.
david55
Moves Like Spencer
 
Posts: 12570
Joined: Fri Sep 26, 2008 5:03 am


Return to AsteriskNOW Support

Who is online

Users browsing this forum: No registered users and 1 guest