Active calls dropped with "The party is not answering" msg

ashcortech · November 15, 2013, 5:50pm

Running FreePBX Distro with Digium D40 phones.

I’ve had this happen a few times in the last week.

A call will be active, either inbound or outbound and within 30 seconds to a minute or two the call will suddenly drop and a message will play that say “The party is not answering…”

Anyone seen this or have any idea what causes it and how to fix it?

here is a copy of the Full.log for one of the incidents.


[2013-11-15 12:14:50] VERBOSE[1829] chan_sip.c:   == Extension Changed auto_hint_203[from-internal] new state InUse for Notify User 203
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [9739774526@from-internal:1] Macro("SIP/203-00000065", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/203-00000065", "TOUCH_MONITOR=1384535690.102") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:2] Set("SIP/203-00000065", "AMPUSER=203") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:3] GotoIf("SIP/203-00000065", "0?report") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:4] ExecIf("SIP/203-00000065", "1?Set(REALCALLERIDNUM=203)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/203-00000065", "AMPUSER=203") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:6] Set("SIP/203-00000065", "AMPUSERCIDNAME=Teresa Home") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:7] GotoIf("SIP/203-00000065", "0?report") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:8] Set("SIP/203-00000065", "AMPUSERCID=203") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:9] Set("SIP/203-00000065", "__DIAL_OPTIONS=Ttr") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:10] Set("SIP/203-00000065", "CALLERID(all)="Teresa Home" <203>") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:11] GotoIf("SIP/203-00000065", "0?limit") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:12] ExecIf("SIP/203-00000065", "1?Set(GROUP(concurrency_limit)=203)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:13] GosubIf("SIP/203-00000065", "7?sub-ccss,s,1(from-internal,9739774526)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-ccss:1] ExecIf("SIP/203-00000065", "0?Return()") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-ccss:2] Set("SIP/203-00000065", "CCSS_SETUP=TRUE") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-ccss:3] GosubIf("SIP/203-00000065", "0?monitor_config,1(from-internal,9739774526):monitor_default,1(from-internal,9739774526)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/203-00000065", "0?is_exten") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/203-00000065", "") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [monitor_default@sub-ccss:3] Return("SIP/203-00000065", "FALSE") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:14] ExecIf("SIP/203-00000065", "0?Set(CHANNEL(language)=)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:15] GotoIf("SIP/203-00000065", "1?continue") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (macro-user-callerid,s,28)
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:28] Set("SIP/203-00000065", "CALLERID(number)=203") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:29] Set("SIP/203-00000065", "CALLERID(name)=Teresa Home") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:30] Set("SIP/203-00000065", "CDR(cnum)=203") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:31] Set("SIP/203-00000065", "CDR(cnam)=Teresa Home") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-user-callerid:32] Set("SIP/203-00000065", "CHANNEL(language)=en") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [9739774526@from-internal:2] Set("SIP/203-00000065", "EMERGENCYROUTE=YES") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [9739774526@from-internal:3] Set("SIP/203-00000065", "MOHCLASS=default") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [9739774526@from-internal:4] Set("SIP/203-00000065", "_NODEST=") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [9739774526@from-internal:5] Gosub("SIP/203-00000065", "sub-record-check,s,1(out,9739774526,)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:1] Set("SIP/203-00000065", "REC_POLICY_MODE_SAVE=") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:2] GotoIf("SIP/203-00000065", "1?check") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (sub-record-check,s,7)
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:7] Set("SIP/203-00000065", "__MON_FMT=wav") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:8] GotoIf("SIP/203-00000065", "1?next") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (sub-record-check,s,11)
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:11] ExecIf("SIP/203-00000065", "0?Return()") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:12] ExecIf("SIP/203-00000065", "0?Set(__REC_POLICY_MODE=)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:13] GotoIf("SIP/203-00000065", "0?out,1") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:14] Set("SIP/203-00000065", "__REC_STATUS=INITIALIZED") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:15] Set("SIP/203-00000065", "NOW=1384535690") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:16] Set("SIP/203-00000065", "__DAY=15") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:17] Set("SIP/203-00000065", "__MONTH=11") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:18] Set("SIP/203-00000065", "__YEAR=2013") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:19] Set("SIP/203-00000065", "__TIMESTR=20131115-121450") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:20] Set("SIP/203-00000065", "__FROMEXTEN=203") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:21] Set("SIP/203-00000065", "__CALLFILENAME=out-9739774526-203-20131115-121450-1384535690.102") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@sub-record-check:22] Goto("SIP/203-00000065", "out,1") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (sub-record-check,out,1)
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [out@sub-record-check:1] ExecIf("SIP/203-00000065", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [out@sub-record-check:2] GosubIf("SIP/203-00000065", "0?record,1(exten,9739774526,203)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [out@sub-record-check:3] Return("SIP/203-00000065", "") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [9739774526@from-internal:6] Macro("SIP/203-00000065", "dialout-trunk,3,9739774526,,off") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("SIP/203-00000065", "DIAL_TRUNK=3") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/203-00000065", "0?sub-pincheck,s,1()") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/203-00000065", "0?disabletrunk,1") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("SIP/203-00000065", "DIAL_NUMBER=9739774526") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("SIP/203-00000065", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("SIP/203-00000065", "OUTBOUND_GROUP=OUT_3") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/203-00000065", "1?nomax") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (macro-dialout-trunk,s,9)
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/203-00000065", "0?skipoutcid") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("SIP/203-00000065", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("SIP/203-00000065", "outbound-callerid,3") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/203-00000065", "0?Set(CALLERPRES()=)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/203-00000065", "0?Set(REALCALLERIDNUM=203)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/203-00000065", "1?normcid") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:6] Set("SIP/203-00000065", "USEROUTCID=") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("SIP/203-00000065", "EMERGENCYCID=") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("SIP/203-00000065", "TRUNKOUTCID=<18882194227>") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/203-00000065", "1?trunkcid") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (macro-outbound-callerid,s,14)
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/203-00000065", "1?Set(CALLERID(all)=<18882194227>)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/203-00000065", "0?Set(CALLERID(all)=)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/203-00000065", "0?Set(CALLERID(all)=)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/203-00000065", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:18] Set("SIP/203-00000065", "CDR(outbound_cnum)=18882194227") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-outbound-callerid:19] Set("SIP/203-00000065", "CDR(outbound_cnam)=") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/203-00000065", "0?sub-flp-3,s,1()") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("SIP/203-00000065", "OUTNUM=9739774526") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("SIP/203-00000065", "custom=SIP/AshcorTelLocal") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/203-00000065", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/203-00000065", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:17] Macro("SIP/203-00000065", "dialout-trunk-predial-hook,") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/203-00000065", "") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/203-00000065", "0?bypass,1") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/203-00000065", "1?Set(CONNECTEDLINE(num,i)=9739774526)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/203-00000065", "1?Set(CONNECTEDLINE(name,i)=CID:18882194227)") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/203-00000065", "0?customtrunk") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:22] Dial("SIP/203-00000065", "SIP/AshcorTelLocal/9739774526,300,Tt") in new stack
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] netsock2.c:   == Using SIP RTP TOS bits 184
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] netsock2.c:   == Using SIP RTP CoS mark 5
[2013-11-15 12:14:50] VERBOSE[16869][C-0000002e] app_dial.c:     -- Called SIP/AshcorTelLocal/9739774526
[2013-11-15 12:14:53] VERBOSE[16869][C-0000002e] app_dial.c:     -- SIP/AshcorTelLocal-00000066 is making progress passing it to SIP/203-00000065
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] app_dial.c:     -- No one is available to answer at this time (1:0/0/0)
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/203-00000065", "Dial failed for some reason with DIALSTATUS = NOANSWER and HANGUPCAUSE = 16") in new stack
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/203-00000065", "0?continue,1:s-NOANSWER,1") in new stack
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] pbx.c:     -- Goto (macro-dialout-trunk,s-NOANSWER,1)
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s-NOANSWER@macro-dialout-trunk:1] NoOp("SIP/203-00000065", "Dial failed due to trunk reporting NOANSWER - giving up") in new stack
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s-NOANSWER@macro-dialout-trunk:2] Progress("SIP/203-00000065", "") in new stack
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s-NOANSWER@macro-dialout-trunk:3] Playback("SIP/203-00000065", "number-not-answering,noanswer") in new stack
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] file.c:     --  Playing 'number-not-answering.alaw' (language 'en')
[2013-11-15 12:15:25] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [s-NOANSWER@macro-dialout-trunk:4] Congestion("SIP/203-00000065", "20") in new stack
[2013-11-15 12:15:25] WARNING[16869][C-0000002e] channel.c: Prodding channel 'SIP/203-00000065' failed
[2013-11-15 12:15:25] VERBOSE[16869][C-0000002e] app_macro.c:   == Spawn extension (macro-dialout-trunk, s-NOANSWER, 4) exited non-zero on 'SIP/203-00000065' in macro 'dialout-trunk'
[2013-11-15 12:15:25] VERBOSE[16869][C-0000002e] pbx.c:   == Spawn extension (from-internal, 9739774526, 6) exited non-zero on 'SIP/203-00000065'
[2013-11-15 12:15:25] VERBOSE[16869][C-0000002e] pbx.c:     -- Executing [h@from-internal:1] Hangup("SIP/203-00000065", "") in new stack
[2013-11-15 12:15:25] VERBOSE[16869][C-0000002e] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/203-00000065'
[2013-11-15 12:15:25] VERBOSE[1829] chan_sip.c:   == Extension Changed auto_hint_203[from-internal] new state Idle for Notify User 202
[2013-11-15 12:15:25] VERBOSE[1829] chan_sip.c:   == Extension Changed auto_hint_203[from-internal] new state Idle for Notify User 203

thanks!

dicko · November 15, 2013, 6:07pm

You need to check with your VSP, it did not complete your call.

[2013-11-15 12:14:53] VERBOSE[16869][C-0000002e] app_dial.c: – SIP/AshcorTelLocal-00000066 is making progress passing it to SIP/203-00000065
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] app_dial.c: – No one is available to answer at this time (1:0/0/0)
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] pbx.c: – Executing [s@macro-dialout-trunk:23] NoOp(“SIP/203-00000065”, “Dial failed for some reason with DIALSTATUS = NOANSWER and HANGUPCAUSE = 16”) in new stack

dicko · November 15, 2013, 6:11pm

It is also possible that your carrier is rejecting the call as you are using

18882194227

callerid(number) should strictly be 10 digits in NANP land.

ashcortech · November 15, 2013, 6:14pm

well the call is actually being answered and there’s a 30 second conversation before it drops. If it was being rejected outright would this be able to happen?

dicko · November 15, 2013, 6:21pm

Well actually from

[2013-11-15 12:14:53] VERBOSE[16869][C-0000002e] app_dial.c: – SIP/AshcorTelLocal-00000066 is making progress passing it to SIP/203-00000065
[2013-11-15 12:15:24] VERBOSE[16869][C-0000002e] app_dial.c: – No one is available to answer at this time (1:0/0/0)

it takes AshcorTelLocal 31 seconds to let you know they can’t complete the call, but the call was not technically answered, as I said, check with AshcorTelLocal. . .

ashcortech · November 15, 2013, 6:29pm

Ok, I’ve opened a ticket with the SIP provider, but just for my understanding, it’s possible for the called party to physically answer and have a 30 second conversation before the sip provider returns a “no answer” to the PBX?

SkykingOH · November 15, 2013, 6:31pm

You may also want to try turning off RPID updates.

ashcortech · November 15, 2013, 6:40pm

“When looking at our CDRs, it appears that you are not sending back an ACK after the 200 OK, which is causing this call to time out. However we would want to setup a live call capture to verify this.”

ashcortech · November 15, 2013, 6:44pm

Sky I assume you mean under Advanced Settings > Sip Send RPID?

it was set to pai.

now set to “no”

SkykingOH · November 15, 2013, 7:25pm

Yes, also trustrpid to no.

Did that fix?

ashcortech · November 15, 2013, 7:32pm

Ok, Trustrpid = no on the advanced settings (default is yes) and both sendrpid and trustrpid on all existing extensions changed to no.

The problem is intermittent which is frustrating so we’ll just have to wait and see.

thanks for the help!

ashcortech · November 23, 2013, 5:00pm

It just happened again today. The SIP SP reports it’s not getting an acknowledgement.

here are the latest logs from today’s event. Notice at the beginning is a mysql error…

I really need to get this fixed.


[2013-11-23 11:43:25] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:6] MessageSend("Message/ast_msg_queue", "sip:192.168.1.20:5060,proxy") in new stack
[2013-11-23 11:43:25] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:7] Hangup("Message/ast_msg_queue", "") in new stack
[2013-11-23 11:43:25] WARNING[1768][C-00000000] channel.c: Exceptionally long queue length queuing to Message/ast_msg_queue
[2013-11-23 11:43:25] VERBOSE[1768][C-00000000] pbx.c: == Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on 'Message/ast_msg_queue'
[2013-11-23 11:45:01] VERBOSE[1811][C-00000003] netsock2.c: == Using SIP RTP TOS bits 184
[2013-11-23 11:45:01] VERBOSE[1811][C-00000003] netsock2.c: == Using SIP RTP CoS mark 5
[2013-11-23 11:45:01] VERBOSE[1772] chan_sip.c: == Extension Changed auto_hint_201[from-internal] new state InUse for Notify User 201
[2013-11-23 11:45:01] VERBOSE[1772] chan_sip.c: == Extension Changed auto_hint_201[from-internal] new state InUse for Notify User 202
[2013-11-23 11:45:01] WARNING[1764] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 Driver]MySQL server has gone away
[2013-11-23 11:45:01] VERBOSE[1772] chan_sip.c: == Extension Changed auto_hint_201[from-internal] new state InUse for Notify User 203
[2013-11-23 11:45:01] WARNING[1764] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5.1.69-log]MySQL server has gone away (69)
[2013-11-23 11:45:01] WARNING[1764] res_odbc.c: SQL Execute error -1! Verifying connection to asteriskcdrdb [MySQL-asteriskcdrdb]...
[2013-11-23 11:45:01] WARNING[1764] res_odbc.c: Connection is down attempting to reconnect...
[2013-11-23 11:45:01] NOTICE[1764] res_odbc.c: Connecting asteriskcdrdb
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [9083036754@from-internal:1] Macro("SIP/201-00000004", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/201-00000004", "TOUCH_MONITOR=1385225101.5") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/201-00000004", "AMPUSER=201") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/201-00000004", "0?report") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/201-00000004", "1?Set(REALCALLERIDNUM=201)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/201-00000004", "AMPUSER=201") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:6] Set("SIP/201-00000004", "AMPUSERCIDNAME=Alan") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:7] GotoIf("SIP/201-00000004", "0?report") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/201-00000004", "AMPUSERCID=201") in new stack
[2013-11-23 11:45:01] NOTICE[1764] res_odbc.c: res_odbc: Connected to asteriskcdrdb [MySQL-asteriskcdrdb]
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/201-00000004", "__DIAL_OPTIONS=Ttr") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/201-00000004", "CALLERID(all)="Alan" <201>") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:11] GotoIf("SIP/201-00000004", "0?limit") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/201-00000004", "1?Set(GROUP(concurrency_limit)=201)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:13] GosubIf("SIP/201-00000004", "7?sub-ccss,s,1(from-internal,9083036754)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/201-00000004", "0?Return()") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/201-00000004", "CCSS_SETUP=TRUE") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/201-00000004", "0?monitor_config,1(from-internal,9083036754):monitor_default,1(from-internal,9083036754)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/201-00000004", "0?is_exten") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/201-00000004", "") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/201-00000004", "FALSE") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:14] ExecIf("SIP/201-00000004", "0?Set(CHANNEL(language)=)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/201-00000004", "1?continue") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Goto (macro-user-callerid,s,28)
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/201-00000004", "CALLERID(number)=201") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/201-00000004", "CALLERID(name)=Alan") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/201-00000004", "CDR(cnum)=201") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/201-00000004", "CDR(cnam)=Alan") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/201-00000004", "CHANNEL(language)=en") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [9083036754@from-internal:2] Set("SIP/201-00000004", "EMERGENCYROUTE=YES") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [9083036754@from-internal:3] Set("SIP/201-00000004", "MOHCLASS=default") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [9083036754@from-internal:4] Set("SIP/201-00000004", "_NODEST=") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [9083036754@from-internal:5] Gosub("SIP/201-00000004", "sub-record-check,s,1(out,9083036754,)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:1] Set("SIP/201-00000004", "REC_POLICY_MODE_SAVE=") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("SIP/201-00000004", "1?check") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Goto (sub-record-check,s,7)
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/201-00000004", "__MON_FMT=wav") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("SIP/201-00000004", "1?next") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Goto (sub-record-check,s,11)
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/201-00000004", "0?Return()") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("SIP/201-00000004", "0?Set(__REC_POLICY_MODE=)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("SIP/201-00000004", "0?out,1") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/201-00000004", "__REC_STATUS=INITIALIZED") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/201-00000004", "NOW=1385225101") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/201-00000004", "__DAY=23") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/201-00000004", "__MONTH=11") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/201-00000004", "__YEAR=2013") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/201-00000004", "__TIMESTR=20131123-114501") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/201-00000004", "__FROMEXTEN=201") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:21] Set("SIP/201-00000004", "__CALLFILENAME=out-9083036754-201-20131123-114501-1385225101.5") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@sub-record-check:22] Goto("SIP/201-00000004", "out,1") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Goto (sub-record-check,out,1)
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/201-00000004", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/201-00000004", "0?record,1(exten,9083036754,201)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/201-00000004", "") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [9083036754@from-internal:6] Macro("SIP/201-00000004", "dialout-trunk,3,9083036754,,off") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/201-00000004", "DIAL_TRUNK=3") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/201-00000004", "0?sub-pincheck,s,1()") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/201-00000004", "0?disabletrunk,1") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/201-00000004", "DIAL_NUMBER=9083036754") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/201-00000004", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/201-00000004", "OUTBOUND_GROUP=OUT_3") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/201-00000004", "1?nomax") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Goto (macro-dialout-trunk,s,9)
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/201-00000004", "0?skipoutcid") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/201-00000004", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/201-00000004", "outbound-callerid,3") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/201-00000004", "0?Set(CALLERPRES()=)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/201-00000004", "0?Set(REALCALLERIDNUM=201)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/201-00000004", "1?normcid") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Goto (macro-outbound-callerid,s,6)
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/201-00000004", "USEROUTCID=") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/201-00000004", "EMERGENCYCID=") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/201-00000004", "TRUNKOUTCID=<9086912377>") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/201-00000004", "1?trunkcid") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Goto (macro-outbound-callerid,s,14)
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/201-00000004", "1?Set(CALLERID(all)=<9086912377>)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/201-00000004", "0?Set(CALLERID(all)=)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/201-00000004", "0?Set(CALLERID(all)=)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/201-00000004", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:18] Set("SIP/201-00000004", "CDR(outbound_cnum)=9086912377") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-outbound-callerid:19] Set("SIP/201-00000004", "CDR(outbound_cnam)=") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/201-00000004", "0?sub-flp-3,s,1()") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/201-00000004", "OUTNUM=9083036754") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/201-00000004", "custom=SIP/AshcorTelLocal") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/201-00000004", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/201-00000004", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/201-00000004", "dialout-trunk-predial-hook,") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/201-00000004", "") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/201-00000004", "0?bypass,1") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/201-00000004", "1?Set(CONNECTEDLINE(num,i)=9083036754)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/201-00000004", "1?Set(CONNECTEDLINE(name,i)=CID:9086912377)") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/201-00000004", "0?customtrunk") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:22] Dial("SIP/201-00000004", "SIP/AshcorTelLocal/9083036754,300,Tt") in new stack
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] netsock2.c: == Using SIP RTP TOS bits 184
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] netsock2.c: == Using SIP RTP CoS mark 5
[2013-11-23 11:45:01] VERBOSE[3653][C-00000003] app_dial.c: -- Called SIP/AshcorTelLocal/9083036754
[2013-11-23 11:45:03] VERBOSE[3653][C-00000003] app_dial.c: -- SIP/AshcorTelLocal-00000005 is making progress passing it to SIP/201-00000004
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] app_dial.c: -- No one is available to answer at this time (1:0/0/0)
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/201-00000004", "Dial failed for some reason with DIALSTATUS = NOANSWER and HANGUPCAUSE = 16") in new stack
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/201-00000004", "0?continue,1:s-NOANSWER,1") in new stack
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] pbx.c: -- Goto (macro-dialout-trunk,s-NOANSWER,1)
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s-NOANSWER@macro-dialout-trunk:1] NoOp("SIP/201-00000004", "Dial failed due to trunk reporting NOANSWER - giving up") in new stack
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s-NOANSWER@macro-dialout-trunk:2] Progress("SIP/201-00000004", "") in new stack
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s-NOANSWER@macro-dialout-trunk:3] Playback("SIP/201-00000004", "number-not-answering,noanswer") in new stack
[2013-11-23 11:45:42] VERBOSE[3653][C-00000003] file.c: --  Playing 'number-not-answering.alaw' (language 'en')
[2013-11-23 11:45:44] VERBOSE[3653][C-00000003] pbx.c: -- Executing [s-NOANSWER@macro-dialout-trunk:4] Congestion("SIP/201-00000004", "20") in new stack
[2013-11-23 11:45:44] WARNING[3653][C-00000003] channel.c: Prodding channel 'SIP/201-00000004' failed
[2013-11-23 11:45:44] VERBOSE[3653][C-00000003] app_macro.c: == Spawn extension (macro-dialout-trunk, s-NOANSWER, 4) exited non-zero on 'SIP/201-00000004' in macro 'dialout-trunk'
[2013-11-23 11:45:44] VERBOSE[3653][C-00000003] pbx.c: == Spawn extension (from-internal, 9083036754, 6) exited non-zero on 'SIP/201-00000004'
[2013-11-23 11:45:44] VERBOSE[3653][C-00000003] pbx.c: -- Executing [h@from-internal:1] Hangup("SIP/201-00000004", "") in new stack
[2013-11-23 11:45:44] VERBOSE[3653][C-00000003] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/201-00000004'
[2013-11-23 11:45:44] VERBOSE[1772] chan_sip.c: == Extension Changed auto_hint_201[from-internal] new state Idle for Notify User 201
[2013-11-23 11:45:44] VERBOSE[1772] chan_sip.c: == Extension Changed auto_hint_201[from-internal] new state Idle for Notify User 202
[2013-11-23 11:45:44] VERBOSE[1772] chan_sip.c: == Extension Changed auto_hint_201[from-internal] new state Idle for Notify User 203
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [proxy@dpma_message_context:1] Set("Message/ast_msg_queue", "MESSAGE(custom_data)=mark_all_outbound") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [proxy@dpma_message_context:2] Set("Message/ast_msg_queue", "MESSAGE_DATA(X-Digium-AppServer-Response-URI)=sip:192.168.1.20:5060") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [proxy@dpma_message_context:3] Set("Message/ast_msg_queue", "MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=sip:192.168.1.20:5060;ob") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [proxy@dpma_message_context:4] MessageSend("Message/ast_msg_queue", "digium_phone:blah") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [proxy@dpma_message_context:5] Hangup("Message/ast_msg_queue", "") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: == Spawn extension (dpma_message_context, proxy, 5) exited non-zero on 'Message/ast_msg_queue'
[2013-11-23 11:45:55] VERBOSE[1792] config.c: == Parsing '/var/spool/asterisk/voicemail/default/202/Old/msg0000.txt': Found
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:1] Set("Message/ast_msg_queue", "MESSAGE(custom_data)=mark_all_outbound") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:2] Set("Message/ast_msg_queue", "TMP_RESPONSE_URI=sip:192.168.1.20:5060") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:3] Set("Message/ast_msg_queue", "MESSAGE_DATA(Request-URI)=sip:192.168.1.20:5060;ob") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:4] Set("Message/ast_msg_queue", "MESSAGE_DATA(X-Digium-AppServer-Response-URI)=") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:5] Set("Message/ast_msg_queue", "MESSAGE_DATA(X-Digium-AppServer-Response-FullContact)=") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:6] MessageSend("Message/ast_msg_queue", "sip:192.168.1.20:5060,proxy") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: -- Executing [digium_phone_module@dpma_message_context:7] Hangup("Message/ast_msg_queue", "") in new stack
[2013-11-23 11:45:55] VERBOSE[1768][C-00000000] pbx.c: == Spawn extension (dpma_message_context, digium_phone_module, 7) exited non-zero on 'Message/ast_msg_queue'

tm1000 · November 24, 2013, 3:42am

The MySQL error is for CDR only. If you completely removed mysql and apache your machine would still work the same, FreePBX is not reliant on those two during operations, only during configuration

ashcortech · November 24, 2013, 2:37pm

Ok, that’s fine but I’m wondering if perhaps the two situations aren’t signs of another issue.

Again this happens randomly, only on outbound calls. The Sip provider says they never receive a 200OK response from the PBX once the call is answered so they disconnect.

Is there anything in the log file I posted that shows this?

ashcortech · December 3, 2013, 11:17pm

This is still an ongoing problem that I need to fix. I have a capture of the UDP traffic on the freepbx box for one of these instances. Anyway I can upload it for here for someone more adept to take a look at?

dicko · December 4, 2013, 4:27am

That wont help, you have a problem with your router not properly maintaining your SIP connection, it is neither Asterisk or FreePBX.

ashcortech · December 4, 2013, 12:46pm

Dicko, yeah I’m beginning to see that the issue lies with the cable company. Spent some time analyzing both sides with my sip provider and although no hard proof is available, it looks like we’re dripping packets/connectino “somewhere.”

Not coincidentally the cable company has been to the location 3 times now for poor internet quality. Random drop offs (there’s that word “random” again) and poor intermittent download speeds.

so it looks like the good news… it’s not the PBX… the bad news… it looks like it is the cable company… the worse news… they’re the only game in town for broadband…

SkykingOH · December 5, 2013, 12:52am

I am sure you can get a T1 from the telco