One particular inbound caller is giving us trouble with FreePBX

grrosenfeldt · January 19, 2017, 11:48pm

Good evening,

As info, we are currently using Free PBX 13.0.190.7 with seven Sangoma s500 phones in our dental office. We use a dedicated SIP trunk provided by our ISP. They deliver it via virtual SBC.

Another dental office is having trouble calling into our system. As far as I know, they are the only one having this trouble. All other calls get through and all outbound calling works as intended

The other dental office is reporting when they dial our number, they either receive a “your call cannot be completed as dialed” message, a busy tone or two beeps followed by silence. Today it was two beeps followed by silence. As this office is making the call, all of our phones will ring normally in the office. However, when a staff member answers the phone, all they hear is our on hold music.

Here is a snippet of the log

[2017-01-19 13:42:48] VERBOSE[29148][C-000000b3] bridge_channel.c: Channel SIP/302-00000246 joined 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] bridge_channel.c: Channel SIP/Midco-00000244 joined 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:48] VERBOSE[29148][C-000000b3] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/302-00000246'
[2017-01-19 13:42:51] VERBOSE[29148][C-000000b3] res_musiconhold.c: Stopped music on hold on SIP/302-00000246
[2017-01-19 13:42:51] VERBOSE[29148][C-000000b3] bridge_channel.c: Channel SIP/302-00000246 left 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] bridge_channel.c: Channel SIP/Midco-00000244 left 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:51] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Idle for Notify User 305 
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] app_macro.c: Spawn extension (macro-dial, s, 19) exited non-zero on 'SIP/Midco-00000244' in macro 'dial'
[2017-01-19 13:42:51] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Idle for Notify User 307 
[2017-01-19 13:42:51] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Idle for Notify User 306 
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Spawn extension (ext-group, 401, 14) exited non-zero on 'SIP/Midco-00000244'
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [h@ext-group:1] Macro("SIP/Midco-00000244", "hangupcall,") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/Midco-00000244", "1?theend") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/Midco-00000244", "0?Set(CDR(recordingfile)=)") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Midco-00000244' in macro 'hangupcall'
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/Midco-00000244'

As you can see, when both parties enter the “simple_bridge” the on hold music starts. And as I’ve stated previously, it’s only with this particular caller as far as I know. Everyone else is able to get through with no trouble at all.

I’m stuck and need a little help.

cynjut · January 20, 2017, 5:33am

Your problem is happening way before the log snippet you sent.

You need to check your inbound routes for their phone number and check the logs to see what the system is doing as soon as they call - basically, the 10 seconds before this snippet.

grrosenfeldt · January 20, 2017, 11:52am

Thanks, Dave. I’m posting the entire event from my log with the hope someone might see the problem. I’ve went through it line by line and the problem is not apparent to me.

First half:

[2017-01-19 13:42:45] VERBOSE[2024][C-000000b3] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-19 13:42:45] VERBOSE[2024][C-000000b3] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:1] Set("SIP/Midco-00000244", "__DIRECTION=INBOUND") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:2] Gosub("SIP/Midco-00000244", "sub-record-check,s,1(in,7013730681,dontcare)") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/Midco-00000244", "0?initialized") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:2] Set("SIP/Midco-00000244", "__REC_STATUS=INITIALIZED") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:3] Set("SIP/Midco-00000244", "NOW=1484854965") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:4] Set("SIP/Midco-00000244", "__DAY=19") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:5] Set("SIP/Midco-00000244", "__MONTH=01") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:6] Set("SIP/Midco-00000244", "__YEAR=2017") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:7] Set("SIP/Midco-00000244", "__TIMESTR=20170119-134245") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:8] Set("SIP/Midco-00000244", "__FROMEXTEN=unknown") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:9] Set("SIP/Midco-00000244", "__MON_FMT=wav") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/Midco-00000244", "Recordings initialized") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/Midco-00000244", "0?Set(ARG3=dontcare)") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:12] Set("SIP/Midco-00000244", "REC_POLICY_MODE_SAVE=") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/Midco-00000244", "0?Set(REC_STATUS=NO)") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/Midco-00000244", "2?checkaction") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/Midco-00000244", "1?sub-record-check,in,1") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/Midco-00000244", "Inbound Recording Check to 7013730681") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [in@sub-record-check:2] Set("SIP/Midco-00000244", "FROMEXTEN=unknown") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/Midco-00000244", "10?Set(FROMEXTEN=7012321956)") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/Midco-00000244", "recordcheck,1(dontcare,in,7013730681)") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/Midco-00000244", "Starting recording check against dontcare") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/Midco-00000244", "dontcare") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [in@sub-record-check:5] Return("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:3] Gosub("SIP/Midco-00000244", "app-blacklist-check,s,1()") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/Midco-00000244", "0?blacklisted") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/Midco-00000244", "CALLED_BLACKLIST=1") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:4] Set("SIP/Midco-00000244", "__FROM_DID=7013730681") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:5] Set("SIP/Midco-00000244", "CDR(did)=7013730681") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:6] ExecIf("SIP/Midco-00000244", "0 ?Set(CALLERID(name)=7012321956)") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:7] Set("SIP/Midco-00000244", "__MOHCLASS=") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:8] Set("SIP/Midco-00000244", "__REVERSAL_REJECT=FALSE") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:9] GotoIf("SIP/Midco-00000244", "1?post-reverse-charge") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (from-trunk,7013730681,11)
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:11] NoOp("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:12] Set("SIP/Midco-00000244", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:13] Set("SIP/Midco-00000244", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:14] Set("SIP/Midco-00000244", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:15] Set("SIP/Midco-00000244", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:16] NoOp("SIP/Midco-00000244", "CallerID Entry Point") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [7013730681@from-trunk:17] Goto("SIP/Midco-00000244", "timeconditions,1,1") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (timeconditions,1,1)
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:1] Set("SIP/Midco-00000244", "DB(TC/1/INUSESTATE)=INUSE") in new stack
[2017-01-19 13:42:45] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:2] Set("SIP/Midco-00000244", "DB(TC/1/NOT_INUSESTATE)=NOT_INUSE") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:3] GotoIfTime("SIP/Midco-00000244", "07:00-16:30,mon-thu,*,*,America/Chicago?truestate") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (timeconditions,1,12)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:12] GotoIf("SIP/Midco-00000244", "0?falsegoto") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:13] ExecIf("SIP/Midco-00000244", "0?Set(DB(TC/1)=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:14] Set("SIP/Midco-00000244", "DEVICE_STATE(Custom:TC1)=NOT_INUSE") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:15] ExecIf("SIP/Midco-00000244", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [1@timeconditions:16] GotoIf("SIP/Midco-00000244", "1?ext-group,401,1") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (ext-group,401,1)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:1] GotoIf("SIP/Midco-00000244", "0?cid") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:2] PlayTones("SIP/Midco-00000244", "ring") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:3] Progress("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:4] Macro("SIP/Midco-00000244", "user-callerid,") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/Midco-00000244", "TOUCH_MONITOR=1484854965.580") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/Midco-00000244", "AMPUSER=7012321956") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/Midco-00000244", "0?report") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/Midco-00000244", "1?Set(REALCALLERIDNUM=7012321956)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/Midco-00000244", "AMPUSER=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/Midco-00000244", "0?limit") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/Midco-00000244", "AMPUSERCIDNAME=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/Midco-00000244", "1?report") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("SIP/Midco-00000244", "0?continue") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:16] ExecIf("SIP/Midco-00000244", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/Midco-00000244", "__TTL=64") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/Midco-00000244", "1?continue") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/Midco-00000244", "CALLERID(number)=7012321956") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/Midco-00000244", "CALLERID(name)=Cook Endodontic") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("SIP/Midco-00000244", "0?cnum") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:32] Set("SIP/Midco-00000244", "CDR(cnam)=Cook Endodontic") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:33] Set("SIP/Midco-00000244", "CDR(cnum)=7012321956") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-user-callerid:34] Set("SIP/Midco-00000244", "CHANNEL(language)=en") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:5] Macro("SIP/Midco-00000244", "blkvm-setifempty,") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/Midco-00000244", "1?init") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-blkvm-setifempty,s,4)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("SIP/Midco-00000244", "__BLKVM_CHANNEL=SIP/Midco-00000244") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("SIP/Midco-00000244", "SHARED(BLKVM,SIP/Midco-00000244)=TRUE") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("SIP/Midco-00000244", "GOSUB_RETVAL=TRUE") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:6] GotoIf("SIP/Midco-00000244", "1?skipov") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (ext-group,401,9)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:9] Set("SIP/Midco-00000244", "RRNODEST=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:10] Set("SIP/Midco-00000244", "__NODEST=401") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:11] GosubIf("SIP/Midco-00000244", "0?sub-rgsetcid,s,1()") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:12] Gosub("SIP/Midco-00000244", "sub-record-check,s,1(rg,401,dontcare)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/Midco-00000244", "10?initialized") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (sub-record-check,s,10)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/Midco-00000244", "Recordings initialized") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/Midco-00000244", "0?Set(ARG3=dontcare)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:12] Set("SIP/Midco-00000244", "REC_POLICY_MODE_SAVE=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/Midco-00000244", "0?Set(REC_STATUS=NO)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/Midco-00000244", "2?checkaction") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/Midco-00000244", "0?sub-record-check,rg,1") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:18] NoOp("SIP/Midco-00000244", "Generic rg Recording Check - 7012321956 401") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:19] Gosub("SIP/Midco-00000244", "recordcheck,1(dontcare,rg,401)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/Midco-00000244", "Starting recording check against dontcare") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/Midco-00000244", "dontcare") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@sub-record-check:20] Return("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:13] Set("SIP/Midco-00000244", "RingGroupMethod=ringall") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [401@ext-group:14] Macro("SIP/Midco-00000244", "dial,15,Ttr,301-302-305-303-304-306") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:1] NoOp("SIP/Midco-00000244", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:2] ExecIf("SIP/Midco-00000244", "0?Set(ALERT_INFO=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:3] ExecIf("SIP/Midco-00000244", "0?Set(ALERT_INFO=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:4] ExecIf("SIP/Midco-00000244", "0?Set(ALERT_INFO=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:5] ExecIf("SIP/Midco-00000244", "0?Set(CHANNEL(musicclass)=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:6] AGI("SIP/Midco-00000244", "dialparties.agi") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Caller ID name is 'Cook Endodontic' number is '7012321956'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Methodology of ring is  'ringall'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Added extension 301 to extension map
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Added extension 302 to extension map
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Added extension 305 to extension map
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Added extension 303 to extension map
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Added extension 304 to extension map
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Added extension 306 to extension map
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 301 cf is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 302 cf is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 305 cf is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 303 cf is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 304 cf is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 306 cf is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 301 do not disturb is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 302 do not disturb is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 305 do not disturb is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 303 do not disturb is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 304 do not disturb is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Extension 306 do not disturb is disabled
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: dbset CALLTRACE/301 to 7012321956
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: dbset CALLTRACE/302 to 7012321956
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: dbset CALLTRACE/305 to 7012321956
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: dbset CALLTRACE/303 to 7012321956
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: dbset CALLTRACE/304 to 7012321956
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: dbset CALLTRACE/306 to 7012321956
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: dialparties.agi: Filtered ARG3: 301-302-305-303-304-306
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] res_agi.c: <SIP/Midco-00000244>AGI Script dialparties.agi completed, returning 0
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:9] NoOp("SIP/Midco-00000244", "Returned from dialparties with groups to dial") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:10] Set("SIP/Midco-00000244", "LOOPCNT=6") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:11] Set("SIP/Midco-00000244", "ITER=1") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:12] Set("SIP/Midco-00000244", "EXTTOCALL=301") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/Midco-00000244", "Working with 301") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:16] Set("SIP/Midco-00000244", "ITER=2") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/Midco-00000244", "1?ndloopbegin") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:12] Set("SIP/Midco-00000244", "EXTTOCALL=302") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/Midco-00000244", "Working with 302") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:16] Set("SIP/Midco-00000244", "ITER=3") in new stack

grrosenfeldt · January 20, 2017, 11:52am

Second half:

[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/Midco-00000244", "1?ndloopbegin") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:12] Set("SIP/Midco-00000244", "EXTTOCALL=305") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/Midco-00000244", "Working with 305") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:16] Set("SIP/Midco-00000244", "ITER=4") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/Midco-00000244", "1?ndloopbegin") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:12] Set("SIP/Midco-00000244", "EXTTOCALL=303") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/Midco-00000244", "Working with 303") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:16] Set("SIP/Midco-00000244", "ITER=5") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/Midco-00000244", "1?ndloopbegin") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:12] Set("SIP/Midco-00000244", "EXTTOCALL=304") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/Midco-00000244", "Working with 304") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:16] Set("SIP/Midco-00000244", "ITER=6") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/Midco-00000244", "1?ndloopbegin") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:12] Set("SIP/Midco-00000244", "EXTTOCALL=306") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/Midco-00000244", "Working with 306") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/Midco-00000244", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:16] Set("SIP/Midco-00000244", "ITER=7") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/Midco-00000244", "0?ndloopbegin") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:18] Macro("SIP/Midco-00000244", "dial-ringall-predial-hook,") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-dial:19] Dial("SIP/Midco-00000244", "SIP/301&SIP/302&SIP/305&SIP/303&SIP/304&SIP/306,15,trM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/301-00000245 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/301-00000245", "Applying SIP Headers to channel") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/301-00000245", "SIPHEADERKEYS=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/301-00000245", "0") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_while.c: Jumping to priority 6
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:7] Return("SIP/301-00000245", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: Spawn extension (from-internal, 401, 1) exited non-zero on 'SIP/301-00000245'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/301-00000245 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/302-00000246 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/302-00000246", "Applying SIP Headers to channel") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/302-00000246", "SIPHEADERKEYS=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/302-00000246", "0") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_while.c: Jumping to priority 6
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:7] Return("SIP/302-00000246", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: Spawn extension (from-internal, 401, 1) exited non-zero on 'SIP/302-00000246'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/302-00000246 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/305-00000247 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/305-00000247", "Applying SIP Headers to channel") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/305-00000247", "SIPHEADERKEYS=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/305-00000247", "0") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_while.c: Jumping to priority 6
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:7] Return("SIP/305-00000247", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: Spawn extension (from-internal, 401, 1) exited non-zero on 'SIP/305-00000247'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/305-00000247 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/303-00000248 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/303-00000248", "Applying SIP Headers to channel") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/303-00000248", "SIPHEADERKEYS=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/303-00000248", "0") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_while.c: Jumping to priority 6
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:7] Return("SIP/303-00000248", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: Spawn extension (from-internal, 401, 1) exited non-zero on 'SIP/303-00000248'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/303-00000248 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/304-00000249 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/304-00000249", "Applying SIP Headers to channel") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/304-00000249", "SIPHEADERKEYS=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/304-00000249", "0") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_while.c: Jumping to priority 6
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:7] Return("SIP/304-00000249", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: Spawn extension (from-internal, 401, 1) exited non-zero on 'SIP/304-00000249'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/304-00000249 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/306-0000024a Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/306-0000024a", "Applying SIP Headers to channel") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/306-0000024a", "SIPHEADERKEYS=") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/306-0000024a", "0") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_while.c: Jumping to priority 6
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@func-apply-sipheaders:7] Return("SIP/306-0000024a", "") in new stack
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: Spawn extension (from-internal, 401, 1) exited non-zero on 'SIP/306-0000024a'
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_stack.c: SIP/306-0000024a Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: Called SIP/301
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: Called SIP/302
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 301[ext-local] new state Ringing for Notify User 305 
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: Called SIP/305
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 301[ext-local] new state Ringing for Notify User 307 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 301[ext-local] new state Ringing for Notify User 306 
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: Called SIP/303
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: Called SIP/304
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Ringing for Notify User 305 
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: Called SIP/306
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Ringing for Notify User 307 
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/306-0000024a connected line has changed. Saving it until answer for SIP/Midco-00000244
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/304-00000249 connected line has changed. Saving it until answer for SIP/Midco-00000244
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/303-00000248 connected line has changed. Saving it until answer for SIP/Midco-00000244
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/305-00000247 connected line has changed. Saving it until answer for SIP/Midco-00000244
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/302-00000246 connected line has changed. Saving it until answer for SIP/Midco-00000244
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/301-00000245 connected line has changed. Saving it until answer for SIP/Midco-00000244
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Ringing for Notify User 306 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse&Ringing for Notify User 304 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse&Ringing for Notify User 302 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse&Ringing for Notify User 301 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse&Ringing for Notify User 303 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Ringing for Notify User 305 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Ringing for Notify User 307 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Ringing for Notify User 304 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Ringing for Notify User 306 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 304[ext-local] new state Ringing for Notify User 302 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 304[ext-local] new state Ringing for Notify User 301 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 304[ext-local] new state Ringing for Notify User 303 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Ringing for Notify User 304 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Ringing for Notify User 302 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Ringing for Notify User 301 
[2017-01-19 13:42:46] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Ringing for Notify User 303 
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/305-00000247 is ringing
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/302-00000246 is ringing
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/301-00000245 is ringing
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/304-00000249 is ringing
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/306-0000024a is ringing
[2017-01-19 13:42:46] VERBOSE[29146][C-000000b3] app_dial.c: SIP/303-00000248 is ringing
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] app_dial.c: SIP/302-00000246 connected line has changed. Saving it until answer for SIP/Midco-00000244
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] app_dial.c: SIP/302-00000246 answered SIP/Midco-00000244
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state InUse for Notify User 305 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state InUse for Notify User 307 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state InUse for Notify User 306 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 301[ext-local] new state Idle for Notify User 305 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 301[ext-local] new state Idle for Notify User 307 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 301[ext-local] new state Idle for Notify User 306 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse for Notify User 304 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse for Notify User 302 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse for Notify User 301 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:1] Set("SIP/302-00000246", "__MACRO_RESULT=") in new stack
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:2] Set("SIP/302-00000246", "CFIGNORE=") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 305[ext-local] new state InUse for Notify User 303 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:3] Set("SIP/302-00000246", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:4] Set("SIP/302-00000246", "FORWARD_CONTEXT=from-internal") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Idle for Notify User 305 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:5] Set("SIP/302-00000246", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Idle for Notify User 307 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:6] Macro("SIP/302-00000246", "blkvm-clr,") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Idle for Notify User 304 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 303[ext-local] new state Idle for Notify User 306 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-clr:1] Set("SIP/302-00000246", "SHARED(BLKVM,SIP/Midco-00000244)=") in new stack
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-clr:2] Set("SIP/302-00000246", "GOSUB_RETVAL=") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 304[ext-local] new state Idle for Notify User 302 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("SIP/302-00000246", "") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 304[ext-local] new state Idle for Notify User 301 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 304[ext-local] new state Idle for Notify User 303 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:7] ExecIf("SIP/302-00000246", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=302)") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Idle for Notify User 304 
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("SIP/302-00000246", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Front Desk 2)") in new stack
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Idle for Notify User 302 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Idle for Notify User 301 
[2017-01-19 13:42:48] VERBOSE[1962] chan_sip.c: Extension Changed 306[ext-local] new state Idle for Notify User 303 
[2017-01-19 13:42:48] VERBOSE[29148][C-000000b3] bridge_channel.c: Channel SIP/302-00000246 joined 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:48] VERBOSE[29146][C-000000b3] bridge_channel.c: Channel SIP/Midco-00000244 joined 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:48] VERBOSE[29148][C-000000b3] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/302-00000246'
[2017-01-19 13:42:51] VERBOSE[29148][C-000000b3] res_musiconhold.c: Stopped music on hold on SIP/302-00000246
[2017-01-19 13:42:51] VERBOSE[29148][C-000000b3] bridge_channel.c: Channel SIP/302-00000246 left 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] bridge_channel.c: Channel SIP/Midco-00000244 left 'simple_bridge' basic-bridge <7be21d8d-dec3-44c0-a3b1-09d503e9be69>
[2017-01-19 13:42:51] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Idle for Notify User 305 
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] app_macro.c: Spawn extension (macro-dial, s, 19) exited non-zero on 'SIP/Midco-00000244' in macro 'dial'
[2017-01-19 13:42:51] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Idle for Notify User 307 
[2017-01-19 13:42:51] VERBOSE[1962] chan_sip.c: Extension Changed 302[ext-local] new state Idle for Notify User 306 
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Spawn extension (ext-group, 401, 14) exited non-zero on 'SIP/Midco-00000244'
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [h@ext-group:1] Macro("SIP/Midco-00000244", "hangupcall,") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/Midco-00000244", "1?theend") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/Midco-00000244", "0?Set(CDR(recordingfile)=)") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/Midco-00000244", "") in new stack
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/Midco-00000244' in macro 'hangupcall'
[2017-01-19 13:42:51] VERBOSE[29146][C-000000b3] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/Midco-00000244'

danielf · January 20, 2017, 12:26pm

Hello,

Can you send the sip debug log (sip set debug on)?

Thank you,

Daniel Friedman
Trixton LTD.

cynjut · January 20, 2017, 2:57pm

I’m not seeing anything that just jumps out of the log file. I did notice that extension 302 seems to be the one that picked up the call, but that looks perfectly reasonable.

Let’s see what the SIP DEBUG says.

grrosenfeldt · January 20, 2017, 4:17pm

I went into the command line and used the command sip set debug on. I’ll have to wait until Monday to see the results. No doctors in the office on a Friday.

grrosenfeldt · January 20, 2017, 11:30pm

Turns out the other dental office was open for a short period today. I had them place a test call with debugging turned on. The behavior was as expected: they heard ringing for a long time followed by a “Your call cannot be completed as dialed” message. When I answered, I got our on-hold music. Phones rang normally with the caller ID showing them calling.

I should add, we are able to make an outbound call to this office with no trouble at all.

I’ve created a web link to the log file here. It’s insane how much is captured in a single call. I can’t post it here.

Thanks again for your help. Hopefully, you’ll be able to see something I don’t.

danielf · January 22, 2017, 9:50am

Hi,

It seems that you are using the same LAN (172.16.100.0). They are sending the internal ip address instead of the public one and it confusing your Asterisk pbx.

What is configured in your sip NAT settings?

Thank you,

Daniel Friedman
Trixton LTD.

grrosenfeldt · January 22, 2017, 5:04pm

Hi, Daniel. You are correct about our LAN setup. However, our sip trunk is on our internal network as well, and shouldn’t be affected by NAT. Our ISP pipes in our trunk via dedicated cable modem, which is hooked into our network switch. It doesn’t traverse the public internet. They have a virtual session border controller setup on their end with an assigned IP of 172.16.100.51. Our FreePBX box is 172.16.100.50.

I did notice some differences with this particular phone call vs. a normal call that has no trouble getting through. I’ve attached the SIP traces and omitted the rest of the log stuff.

[2017-01-20 14:39:37] VERBOSE[2035] chan_sip.c:
<--- SIP read from UDP:172.16.100.51:5060 --->
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKcc4898d2c2503880bf8dbd76e130c9e0.0
Session-Expires: 14400
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK7c1f7301d0160f5ae0a8882cc4860c26.by-It0q-l0l-rnx0iq3IwQ__
To: <sip:[email protected]>
From: "Cook Endodontic" <sip:[email protected]>;tag=3aad7c6f
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 1 INVITE
User-Agent: SIParator/5.0.11
Contact: <sip:[email protected]>
Supported: timer, replaces, path, histinfo, 100rel
Allow: ACK, CANCEL, BYE, INFO, INVITE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE
Max-Forwards: 17
X-Nt-Corr-Id: 163f9285-d1c0-42f4-a3f9-bc67031f94e7
X-Nt-Location: -1
P-Charging-Vector: icid-value=163f9285-d1c0-42f4-a3f9-bc67031f94e7;icid-generated-at=10.99.8.221
Content-Type: application/sdp
Content-Length: 292
Record-Route: <sip:[email protected];lr>
 
v=0
o=trunk1.0 1278 683073728 IN IP4 172.16.100.51
s=sip call
c=IN IP4 172.16.100.51
t=0 0
m=audio 59268 RTP/AVP 0 101
b=AS:80
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000/1
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 audio RTP/AVP 0 8 101
a=cdsc: 4 image udptl t38
<------------->

[2017-01-20 14:39:37] VERBOSE[2035][C-00000031] chan_sip.c:
<--- Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKcc4898d2c2503880bf8dbd76e130c9e0.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK7c1f7301d0160f5ae0a8882cc4860c26.by-It0q-l0l-rnx0iq3IwQ__
Record-Route: <sip:[email protected];lr>
From: "Cook Endodontic" <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 1 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Length: 0
 
 
<------------>

<--- Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKcc4898d2c2503880bf8dbd76e130c9e0.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK7c1f7301d0160f5ae0a8882cc4860c26.by-It0q-l0l-rnx0iq3IwQ__
Record-Route: <sip:[email protected];lr>
From: "Cook Endodontic" <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>;tag=as2ec45375
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 1 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 254
 
v=0
o=root 1550430259 1550430259 IN IP4 172.16.100.50
s=Asterisk PBX 13.12.1
c=IN IP4 172.16.100.50
t=0 0
m=audio 11966 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
 
<------------>

[2017-01-20 14:39:45] VERBOSE[30472][C-00000031] chan_sip.c:
<--- Reliably Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKcc4898d2c2503880bf8dbd76e130c9e0.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK7c1f7301d0160f5ae0a8882cc4860c26.by-It0q-l0l-rnx0iq3IwQ__
Record-Route: <sip:[email protected];lr>
From: "Cook Endodontic" <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>;tag=as2ec45375
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 1 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 254
 
v=0
o=root 1550430259 1550430259 IN IP4 172.16.100.50
s=Asterisk PBX 13.12.1
c=IN IP4 172.16.100.50
t=0 0
m=audio 11966 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
 
<------------>

[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c: --- (9 headers 0 lines) ---
[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c:
<--- SIP read from UDP:172.16.100.51:5060 --->
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKdb6cb0590d98786610208395b125648a.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK5c050d1ffe85803f7fd79b0a0cc44472.wtx2jLAQ+hT1lKDOU6zHsA__
To: <sip:[email protected]>;tag=as2ec45375
From: <sip:[email protected]>;tag=3aad7c6f
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 1 ACK
Max-Forwards: 69
User-Agent: SIParator/5.0.11
Content-Length: 0
 
<------------->

[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c: --- (10 headers 0 lines) ---
[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c:
<--- SIP read from UDP:172.16.100.51:5060 --->
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK12f616b712b837bd10208395b125648a.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKb2683e73c9200f3f4a0635597a1c3f7e.vsyLY9gY1rbdOXNgdtqYxQ__
To: <sip:[email protected]>;tag=as2ec45375
From: <sip:[email protected]>;tag=3aad7c6f
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 2 INVITE
User-Agent: SIParator/5.0.11
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]>
Supported: timer, replaces, path, histinfo, 100rel
Max-Forwards: 17
X-Nt-Location: -1
Content-Type: application/sdp
Content-Length: 304
 
v=0
o=trunk1.0 1278 683073729 IN IP4 172.16.100.51
s=sip call
c=IN IP4 172.16.100.51
t=0 0
m=audio 59270 RTP/AVP 0 101
b=AS:80
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000/1
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 audio RTP/AVP 0 8 101
a=cdsc: 4 image udptl t38
a=sendonly
<------------->

<--- Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK12f616b712b837bd10208395b125648a.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKb2683e73c9200f3f4a0635597a1c3f7e.vsyLY9gY1rbdOXNgdtqYxQ__
From: <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>;tag=as2ec45375
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 2 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Length: 0
 
 
<------------>

[2017-01-20 14:39:45] VERBOSE[2035][C-00000031] chan_sip.c:
<--- Reliably Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK12f616b712b837bd10208395b125648a.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKb2683e73c9200f3f4a0635597a1c3f7e.vsyLY9gY1rbdOXNgdtqYxQ__
From: <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>;tag=as2ec45375
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 2 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 254
 
v=0
o=root 1550430259 1550430260 IN IP4 172.16.100.50
s=Asterisk PBX 13.12.1
c=IN IP4 172.16.100.50
t=0 0
m=audio 11966 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=recvonly
 
<------------>

<------------->
[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c: --- (9 headers 0 lines) ---
[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c:
<--- SIP read from UDP:172.16.100.51:5060 --->
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKdb6cb0590d98786610208395b125648a.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK5c050d1ffe85803f7fd79b0a0cc44472.wtx2jLAQ+hT1lKDOU6zHsA__
To: <sip:[email protected]>;tag=as2ec45375
From: <sip:[email protected]>;tag=3aad7c6f
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 1 ACK
Max-Forwards: 69
User-Agent: SIParator/5.0.11
Content-Length: 0
 
<------------->
[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c: --- (10 headers 0 lines) ---
[2017-01-20 14:39:45] VERBOSE[2035] chan_sip.c:
<--- SIP read from UDP:172.16.100.51:5060 --->
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK12f616b712b837bd10208395b125648a.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKb2683e73c9200f3f4a0635597a1c3f7e.vsyLY9gY1rbdOXNgdtqYxQ__
To: <sip:[email protected]>;tag=as2ec45375
From: <sip:[email protected]>;tag=3aad7c6f
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 2 INVITE
User-Agent: SIParator/5.0.11
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]>
Supported: timer, replaces, path, histinfo, 100rel
Max-Forwards: 17
X-Nt-Location: -1
Content-Type: application/sdp
Content-Length: 304
 
v=0
o=trunk1.0 1278 683073729 IN IP4 172.16.100.51
s=sip call
c=IN IP4 172.16.100.51
t=0 0
m=audio 59270 RTP/AVP 0 101
b=AS:80
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000/1
a=fmtp:101 0-15
a=ptime:20
a=sqn: 0
a=cdsc: 1 audio RTP/AVP 0 8 101
a=cdsc: 4 image udptl t38
a=sendonly
<------------->

<--- Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK12f616b712b837bd10208395b125648a.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKb2683e73c9200f3f4a0635597a1c3f7e.vsyLY9gY1rbdOXNgdtqYxQ__
From: <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>;tag=as2ec45375
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 2 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Length: 0
 
 
<------------>

<--- Reliably Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK12f616b712b837bd10208395b125648a.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bKb2683e73c9200f3f4a0635597a1c3f7e.vsyLY9gY1rbdOXNgdtqYxQ__
From: <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>;tag=as2ec45375
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 2 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: <sip:[email protected]:5060>
Content-Type: application/sdp
Require: timer
Content-Length: 254
 
v=0
o=root 1550430259 1550430260 IN IP4 172.16.100.50
s=Asterisk PBX 13.12.1
c=IN IP4 172.16.100.50
t=0 0
m=audio 11966 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=recvonly
 
<------------>

[2017-01-20 14:39:53] VERBOSE[2035] chan_sip.c:
<--- SIP read from UDP:172.16.100.51:5060 --->
BYE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK905c98674cda6c1610208395b125648a.0
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK0a6f85509074f90b4546e830a9c49450.mOC89yovh18fAQ7WITcYng__
To: <sip:[email protected]>;tag=as2ec45375
From: <sip:[email protected]>;tag=3aad7c6f
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 3 BYE
Max-Forwards: 69
User-Agent: SIParator/5.0.11
Content-Length: 0
 
<------------->
[2017-01-20 14:39:53] VERBOSE[2035] chan_sip.c: --- (10 headers 0 lines) ---
[2017-01-20 14:39:53] VERBOSE[2035][C-00000031] chan_sip.c: Sending to 172.16.100.51:5060 (NAT)
[2017-01-20 14:39:53] VERBOSE[2035][C-00000031] chan_sip.c: Scheduling destruction of SIP dialog 'e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420' in 6400 ms (Method: BYE)
[2017-01-20 14:39:53] VERBOSE[2035][C-00000031] chan_sip.c:
<--- Transmitting (NAT) to 172.16.100.51:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK905c98674cda6c1610208395b125648a.0;received=172.16.100.51;rport=5060
Via: SIP/2.0/UDP 172.16.100.51:5060;branch=z9hG4bK0a6f85509074f90b4546e830a9c49450.mOC89yovh18fAQ7WITcYng__
From: <sip:[email protected]>;tag=3aad7c6f
To: <sip:[email protected]>;tag=as2ec45375
Call-ID: e1a80c1fac6a5a3a88c49f4aa283909c@sipgt-1927a420
CSeq: 3 BYE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0
 
 
<------------>

During the call I’ve noticed a few differences from a good call, like lines stating a=sendonly, a=recvonly, 183 Session Progress. I don’t see those things in a successful inbound call.

This is the only caller that is giving us trouble. Everyone else can dial in just fine and we can dial out with no problems.

danielf · January 23, 2017, 2:22pm

Hello,

Can you send me your NAT settings in the sip settings module?
Furthermore, the “problematic” client is calling your office through its own SIP trunk? or is it connected to your PBX?

Thank you,

Daniel Friedman
Trixton LTD.

grrosenfeldt · January 23, 2017, 11:33pm

Screen shots attached below.

Also, these are my outbound trunk settings:

type=peer
host=172.16.100.51
qualify=yes
nat=no
context=from-trunk
disallow=all
allow=ulaw

This particular office is calling from the PSTN. I don’t know what kind of system they have on the other end. I figure it should be treated like the other 50 calls per day that coming in and go out without any trouble.

danielf · January 24, 2017, 10:06am

Hello,

Please add your SIP trunk network to the local lan settings. According to your explanations and logs, your local networks are:

172.16.50.0/24 (Local Lan)
172.16.51.0/24 (SIP trunk provider)
172.16.100.0/24 (Cook Endodontic)

Add these networks to your local net settings.

Can you send me your routing table from the pbx (netstat -rn)?
It seems now, that the pbx is routing the answer packets to the default gateway instead to your SIP trunk gateway.

Thank you,

Daniel Friedman
Trixton LTD.

grrosenfeldt · January 27, 2017, 1:04am

Found the fix.

Had to add “canreinvite=no” to my sip trunk outgoing settings. Seems to have resolved the problem.

lgaetz · January 27, 2017, 1:44am

I’'m curious to know what do you have set for ‘Reinvite Behavior’ under Settings, Asterisk SIP Settings, Chan SIP tab? By default reinvite should be disabled.

grrosenfeldt · January 27, 2017, 2:07am

Reinvite behavior is set to no.

I guess I’ll have to give some time to see if the problem pops up again. I’m only guessing my change to the outgoing settings fixed the problem.