FreePBX hanging up on Sangoma Phone during missed call

mdoupe · May 17, 2018, 10:12pm

Hiya,

I am having a very odd issue. I have a Sangoma S500 that receives a lot of calls (it’s the first point of contact for a department). Occasionally when the person is on a call with a person (CallingNumber1 in the attached log) and a second person calls in (CallingNumber2), when the second person (I think) leaves a voicemail, the first call, with CallingNumber1 is disconnected.

All the pertinent info I can think of:

The whole department has S500 phones, and they are all subscribed to each other with BLF’s, but when this happens, nobody else is picking up either call. The first call is picked up by CalledNumber, and the second call goes unanswered (Ring time is 20 seconds in FreePBX)

This does not happen at all on the Cisco phones used with the same FreePBX install.

I’m on the latest S500 firmware, 2.0.4.48.

The phone has a plantronics headset with an EHS. It’s quite a big ask to have them eliminate the headset for troubleshooting purposes, so I’m hoping it does not come to that. I think the BYE is coming from FreePBX in the log, though?

I’ve pasted (in 2 parts) the scrubbed log from the phone below. First invite is at 20:19:02, second invite is at 20:20:26. Unexpected BYE is at 20:20:55. Please let me know if any more info is needed.

2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012INVITE sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK1ef1f637#015#012Max-Forwards: 70#015#012From: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>:5160>;tag=as55945b35#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Contact: <sip:<CallingNumber1>@<FreePBXIP>:5160>#015#012Call-ID: 0a3d82e041edcf0c61dd50675d173c66@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Date: Thu, 17 May 2018 20:19:02 GMT#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE#015#012Supported: replaces, timer#015#012Remote-Party-ID: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>>;party=calling;privacy=off;screen=no#015#012Content-Type: application/sdp#015#012Content-Length: 276#015#012#015#012v=0#015#012o=root 1165576737 1165576737 IN IP4 <FreePBXIP>#015#012s=Asterisk PBX 13.18.0#015#012c=IN IP4 <FreePBXIP>#015#012t=0 0#015#012m=audio 16850 RTP/AVP 0 8 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ptime:20#015#012a=maxptime:150#015#012a=sendrecv#015#012
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 100 Trying#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK1ef1f637#015#012From: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>:5160>;tag=as55945b35#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Call-ID: 0a3d82e041edcf0c61dd50675d173c66@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, tid 5890, did 115, REQUEST: INVITE, Event: 5
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, tid 5890, did 115, RESPONSE: 101 Dialog Establishement, New call received!, Event: 5
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : eXosip_get_sdp_info:240-->>>>>>>SIP Parse Normal SDP Body<<<<<<<#015
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : >>>>>>>Set ACD Info Error!!--MimeType=0,aid=0<<<<<<<#015
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : ###SDP INFO########Addr Type=IP4---NetType=IN---Addr=<FreePBXIP>###################015
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, SDP Payload pos 0, Type 0(0)
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, SDP Payload pos 0, Type 0
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: Check CFG Setting, Match index_0, CodecType 0
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: SDP IP <FreePBXIP>, Port 16850, Interval 2, codec 0, audio 0, direct 3
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: SDP IP <FreePBXIP>, Port 16850, Interval 2, codec 0, audio 0, direct 3
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro active_url sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro local_uri sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro remote_uri sip:<CallingNumber1>@<FreePBXIP>:5160
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallInvite_Setup2CallCtl:5049====Check User Id Over!!======#015
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x60, Event=0x300, Chn=0#015
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: Get Idle Line 0 (aid 0)
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : chn=0, AEC_switch = 0
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : MS: Chn 0 MSDspStopSendRev
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : CfgGetRingId::9315--------Play Ring Tone--RingType=15--RingId=1-#015
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: Play RingTone 1
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : Ti3100:HEADSET_SPEAKEK_OUT mode 
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : BSPOpenRingHeadset:1464===>>>RingingVolume 5, flag=1#015
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : MS: tid 1 Req Play RingTone
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8d5
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : L2C: IncomingCall: aid 0, line 0, CID <CallingNumber1>
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012NOTIFY sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK546c470b#015#012Max-Forwards: 70#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Contact: <sip:<CalledNumber>@<FreePBXIP>:5160>#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 561 NOTIFY#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Subscription-State: active#015#012Event: dialog#015#012Content-Type: application/dialog-info+xml#015#012Content-Length: 229#015#012#015#012<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="459" state="full" entity="sip:<CalledNumber>@<FreePBXIP>:5160">#012<dialog id="<CalledNumber>" direction="recipient">#012<state>early</state>#012</dialog>#012</dialog-info>#012
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5891, did 5, REQUEST: NOTIFY, Event: 43
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK546c470b#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 561 NOTIFY#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 180 Ringing#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK1ef1f637#015#012From: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>:5160>;tag=as55945b35#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=1a613474d7035e1#015#012Call-ID: 0a3d82e041edcf0c61dd50675d173c66@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012Contact: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_INCOMING, Index:0
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: MSG_PAINT
2018-05-17T20:19:02-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: num:0,HLGUIData.ScrewView.ScrewItemNum:0

2018-05-17T20:19:07-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x63, Event=0x1023, Chn=0#015

2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : FXSCALL EHS State Change to STATE_EHS_OFF_HOOK!!#015
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: CSGetVirtualIdleLine, aid 0, VirtualLine 57#015
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : Ti3100:HEADSET mode 
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x63, Event=0x100, Chn=0#015
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : MS: tid 1 Req Stop RingTone
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8d6
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: sdp_message_pro: Local IP is <PhoneIP>
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: sdp_message - CodecType 0
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0 tid 5890 send status 200 answer success
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0 tid 5890 send status 200 answer success
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK1ef1f637#015#012From: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>:5160>;tag=as55945b35#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=1a613474d7035e1#015#012Call-ID: 0a3d82e041edcf0c61dd50675d173c66@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012Contact: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Type: application/sdp#015#012Content-Length: 210#015#012#015#012v=0#015#012o=- 6666 49 IN IP4 <PhoneIP>#015#012s=SIP Call#015#012c=IN IP4 <PhoneIP>#015#012t=0 0#015#012m=audio 12184 RTP/AVP 0 101#015#012a=sendrecv#015#012a=rtpmap:0 PCMU/8000#015#012a=ptime:20#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-11,16#015#012
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012ACK sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK01467fe5#015#012Max-Forwards: 70#015#012From: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>:5160>;tag=as55945b35#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=1a613474d7035e1#015#012Contact: <sip:<CallingNumber1>@<FreePBXIP>:5160>#015#012Call-ID: 0a3d82e041edcf0c61dd50675d173c66@<FreePBXIP>:5160#015#012CSeq: 102 ACK#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, tid 0, did 115, ACK received!
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : eXosip_get_sdp_info:240-->>>>>>>SIP Parse Normal SDP Body<<<<<<<#015
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro local_uri sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro remote_uri sip:<CallingNumber1>@<FreePBXIP>:5160
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro local_uri sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro remote_uri sip:<CallingNumber1>@<FreePBXIP>:5160
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x62, Event=0x205, Chn=0#015
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : chn=0, AEC_switch = 1
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : MS: Chn 0 MSDspSetSendRev
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012NOTIFY sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK4f6ea641#015#012Max-Forwards: 70#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Contact: <sip:<CalledNumber>@<FreePBXIP>:5160>#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 562 NOTIFY#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Subscription-State: active#015#012Event: dialog#015#012Content-Type: application/dialog-info+xml#015#012Content-Length: 211#015#012#015#012<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="460" state="full" entity="sip:<CalledNumber>@<FreePBXIP>:5160">#012<dialog id="<CalledNumber>">#012<state>confirmed</state>#012</dialog>#012</dialog-info>#012
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5892, did 5, REQUEST: NOTIFY, Event: 43
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK4f6ea641#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 562 NOTIFY#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_OFFHOOKTYPE:3
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_INCOMING_OK, Index:0
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : Chn 0 seq 13195 error(last seq 14987)
2018-05-17T20:19:09-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI:DEBUGINFO:CallFailureInfoShow!,File:./src/callwin.c------Line:4105

2018-05-17T20:19:12-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x1023, Chn=0#015
2018-05-17T20:19:14-06:00 <PhoneIP> [S500][<PhoneMAC>] : RTP Send: SrcIP ac1408ef, SrcPort 12185 miss-match, need Re_InitUDPSocket
2018-05-17T20:19:14-06:00 <PhoneIP> [S500][<PhoneMAC>] : Init UDPSocket: close the socket 8 from pos 2 !
2018-05-17T20:19:14-06:00 <PhoneIP> [S500][<PhoneMAC>] : IPV4 Init UDPSocket: bind socket 8 Success, pos[2]locip[ac1408ef]port[12185]!

2018-05-17T20:19:21-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012OPTIONS sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK5c26ee9b#015#012Max-Forwards: 70#015#012From: "Unknown" <sip:Unknown@<FreePBXIP>:5160>;tag=as4997ba00#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Contact: <sip:Unknown@<FreePBXIP>:5160>#015#012Call-ID: 6c48ac0344dcfb8f5d926a3846b48685@<FreePBXIP>:5160#015#012CSeq: 102 OPTIONS#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Date: Thu, 17 May 2018 20:19:21 GMT#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE#015#012Supported: replaces, timer#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:19:21-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5893, did 0, REQUEST: OPTIONS, Event: 27
2018-05-17T20:19:21-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK5c26ee9b#015#012From: "Unknown" <sip:Unknown@<FreePBXIP>:5160>;tag=as4997ba00#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=bb3d4b84a32f6b3#015#012Call-ID: 6c48ac0344dcfb8f5d926a3846b48685@<FreePBXIP>:5160#015#012CSeq: 102 OPTIONS#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012

2018-05-17T20:20:14-06:00 <PhoneIP> [S500][<PhoneMAC>] : Internal RTCP NTP clock skew detected: lsr=627a0000, dlsr=0004a3d7, now=627ea3cd, eedelay=00000000

2018-05-17T20:20:19-06:00 <PhoneIP> [S500][<PhoneMAC>] : Internal RTCP NTP clock skew detected: lsr=627f051e, dlsr=00049eb8, now=6283a3cd, eedelay=00000000

2018-05-17T20:20:21-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012OPTIONS sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK77270f85#015#012Max-Forwards: 70#015#012From: "Unknown" <sip:Unknown@<FreePBXIP>:5160>;tag=as3493d2ab#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Contact: <sip:Unknown@<FreePBXIP>:5160>#015#012Call-ID: 268858993488bb6a47ef1b47333129af@<FreePBXIP>:5160#015#012CSeq: 102 OPTIONS#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Date: Thu, 17 May 2018 20:20:21 GMT#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE#015#012Supported: replaces, timer#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:21-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5894, did 0, REQUEST: OPTIONS, Event: 27
2018-05-17T20:20:21-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK77270f85#015#012From: "Unknown" <sip:Unknown@<FreePBXIP>:5160>;tag=as3493d2ab#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=e1823cd414c8e7d#015#012Call-ID: 268858993488bb6a47ef1b47333129af@<FreePBXIP>:5160#015#012CSeq: 102 OPTIONS#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012

2018-05-17T20:20:24-06:00 <PhoneIP> [S500][<PhoneMAC>] : RTT = 5872 us, RTT mean =  1708 us
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012INVITE sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK646b7a91#015#012Max-Forwards: 70#015#012From: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>:5160>;tag=as72a657bb#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Contact: <sip:<CallingNumber2>@<FreePBXIP>:5160>#015#012Call-ID: 23e589e5278429925f3b5f4951d8a273@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Date: Thu, 17 May 2018 20:20:26 GMT#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE#015#012Supported: replaces, timer#015#012Remote-Party-ID: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>>;party=calling;privacy=off;screen=no#015#012Content-Type: application/sdp#015#012Content-Length: 274#015#012#015#012v=0#015#012o=root 594739870 594739870 IN IP4 <FreePBXIP>#015#012s=Asterisk PBX 13.18.0#015#012c=IN IP4 <FreePBXIP>#015#012t=0 0#015#012m=audio 17484 RTP/AVP 0 8 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ptime:20#015#012a=maxptime:150#015#012a=sendrecv#015#012
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 100 Trying#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK646b7a91#015#012From: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>:5160>;tag=as72a657bb#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Call-ID: 23e589e5278429925f3b5f4951d8a273@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 116, tid 5895, did 117, REQUEST: INVITE, Event: 5
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 116, tid 5895, did 117, RESPONSE: 101 Dialog Establishement, New call received!, Event: 5
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : eXosip_get_sdp_info:240-->>>>>>>SIP Parse Normal SDP Body<<<<<<<#015
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : >>>>>>>Set ACD Info Error!!--MimeType=0,aid=0<<<<<<<#015
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : ###SDP INFO########Addr Type=IP4---NetType=IN---Addr=<FreePBXIP>###################015
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, SDP Payload pos 0, Type 0(0)
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, SDP Payload pos 0, Type 0
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: Check CFG Setting, Match index_0, CodecType 0
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: SDP IP <FreePBXIP>, Port 17484, Interval 2, codec 0, audio 0, direct 3
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: SDP IP <FreePBXIP>, Port 17484, Interval 2, codec 0, audio 0, direct 3
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro active_url sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro local_uri sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro remote_uri sip:<CallingNumber2>@<FreePBXIP>:5160
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallInvite_Setup2CallCtl:5049====Check User Id Over!!======#015
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012NOTIFY sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK4c40ef69#015#012Max-Forwards: 70#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Contact: <sip:<CalledNumber>@<FreePBXIP>:5160>#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 563 NOTIFY#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Subscription-State: active#015#012Event: dialog#015#012Content-Type: application/dialog-info+xml#015#012Content-Length: 229#015#012#015#012<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="461" state="full" entity="sip:<CalledNumber>@<FreePBXIP>:5160">#012<dialog id="<CalledNumber>" direction="recipient">#012<state>early</state>#012</dialog>#012</dialog-info>#012
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5896, did 5, REQUEST: NOTIFY, Event: 43
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK4c40ef69#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 563 NOTIFY#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x300, Chn=0#015
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: CSGetVirtualIdleLine, aid 0, VirtualLine 57#015
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: Get Idle Line 57 (aid 0)
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: cw_tone.Frequency1:440
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: cw_tone.Frequency2:440
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: cw_tone.On_Period1:30,cw_tone.Off_Period1:1000
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: cw_tone.On_Period2:0,cw_tone.Off_Period2:0
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: cw_tone.On_Period3:0,cw_tone.Off_Period3:0
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 57, event 0x8d5
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 180 Ringing#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK646b7a91#015#012From: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>:5160>;tag=as72a657bb#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=332911f0bdae751#015#012Call-ID: 23e589e5278429925f3b5f4951d8a273@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012Contact: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : L2C: IncomingCall: aid 0, line 57, CID <CallingNumber2>
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_INCOMING, Index:57
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI:DEBUGINFO:CallFailureInfoShow!,File:./src/callwin.c------Line:4105
2018-05-17T20:20:26-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x1003, Chn=0#015

2018-05-17T20:20:32-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012NOTIFY sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK7b99e309#015#012Max-Forwards: 70#015#012From: <sip:8008@<FreePBXIP>:5160>;tag=as54776eea#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=a8337bf05246e2b#015#012Contact: <sip:8008@<FreePBXIP>:5160>#015#012Call-ID: e67d2772587af28@<PhoneIP>#015#012CSeq: 293 NOTIFY#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Subscription-State: active#015#012Event: dialog#015#012Content-Type: application/dialog-info+xml#015#012Content-Length: 212#015#012#015#012<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="191" state="full" entity="sip:8008@<FreePBXIP>:5160">#012<dialog id="8008">#012<state>terminated</state>#012</dialog>#012</dialog-info>#012
2018-05-17T20:20:32-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5897, did 59, REQUEST: NOTIFY, Event: 43
2018-05-17T20:20:32-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK7b99e309#015#012From: <sip:8008@<FreePBXIP>:5160>;tag=as54776eea#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=a8337bf05246e2b#015#012Call-ID: e67d2772587af28@<PhoneIP>#015#012CSeq: 293 NOTIFY#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012

2018-05-17T20:20:34-06:00 <PhoneIP> [S500][<PhoneMAC>] : Internal RTCP NTP clock skew detected: lsr=628e2145, dlsr=0004828f, now=6292a3cd, eedelay=00000000

mdoupe · May 17, 2018, 10:17pm

2018-05-17T20:20:36-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x1003, Chn=0#015
2018-05-17T20:20:37-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x1003, Chn=0#015
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP REFRESH####Alive Time=271######js->s_reg_period=300#############015
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: sip_nict_init, no route, req_uri->host:port is <FreePBXIP>:5160
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SUBSCRIBE sip:<CalledNumber>@<FreePBXIP>:5160 SIP/2.0#015#012Via: SIP/2.0/UDP <PhoneIP>:5060;branch=z9hG4bK229032219#015#012From: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012To: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 970 SUBSCRIBE#015#012Contact: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Max-Forwards: 70#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Expires: 300#015#012Event: dialog#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Accept: application/dialog-info+xml#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 401 Unauthorized#015#012Via: SIP/2.0/UDP <PhoneIP>:5060;branch=z9hG4bK229032219;received=<PhoneIP>#015#012From: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012To: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 970 SUBSCRIBE#015#012Server: FPBX-13.0.194.2(13.18.0)#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE#015#012Supported: replaces, timer#015#012WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="1da145ec"#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5898, did 5, REQUEST: SUBSCRIBE, Event: 40
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5898, did 5, RESPONSE: 401 Unauthorized, 4xx received for SUBSCRIBE!, Event: 40
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: find_authentication_info, aid 0, username: <CalledNumber>, realm: "asterisk"
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: find_auth_info, aid 0, username: <CalledNumber>, account match
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: sip_nict_init, no route, req_uri->host:port is <FreePBXIP>:5160
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SUBSCRIBE sip:<CalledNumber>@<FreePBXIP>:5160 SIP/2.0#015#012Via: SIP/2.0/UDP <PhoneIP>:5060;branch=z9hG4bK94d1d161#015#012From: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012To: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 971 SUBSCRIBE#015#012Contact: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Authorization: Digest username="<CalledNumber>", realm="asterisk", nonce="1da145ec", uri="sip:<CalledNumber>@<FreePBXIP>:5160", response="0b9779913102632f909fab02a1710ea7", algorithm=MD5#015#012Max-Forwards: 70#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Expires: 300#015#012Event: dialog#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Accept: application/dialog-info+xml#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <PhoneIP>:5060;branch=z9hG4bK94d1d161;received=<PhoneIP>#015#012From: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012To: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 971 SUBSCRIBE#015#012Server: FPBX-13.0.194.2(13.18.0)#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE#015#012Supported: replaces, timer#015#012Expires: 300#015#012Contact: <sip:<CalledNumber>@<FreePBXIP>:5160>;expires=300#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5899, did 5, REQUEST: SUBSCRIBE, Event: 38
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5899, did 5, RESPONSE: 200 OK, 2xx received for SUBSCRIBE!, Event: 38
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: Event SIP_SUBSCRIPTION_ANSWERED#015
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, Dsskey 4, Subscribe Response Status 200
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012NOTIFY sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK32b3f522#015#012Max-Forwards: 70#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Contact: <sip:<CalledNumber>@<FreePBXIP>:5160>#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 564 NOTIFY#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Subscription-State: active#015#012Event: dialog#015#012Content-Type: application/dialog-info+xml#015#012Content-Length: 229#015#012#015#012<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="462" state="full" entity="sip:<CalledNumber>@<FreePBXIP>:5160">#012<dialog id="<CalledNumber>" direction="recipient">#012<state>early</state>#012</dialog>#012</dialog-info>#012
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5900, did 5, REQUEST: NOTIFY, Event: 43
2018-05-17T20:20:38-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK32b3f522#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 564 NOTIFY#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012

2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012CANCEL sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK646b7a91#015#012Max-Forwards: 70#015#012From: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>:5160>;tag=as72a657bb#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>#015#012Call-ID: 23e589e5278429925f3b5f4951d8a273@<FreePBXIP>:5160#015#012CSeq: 102 CANCEL#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 116, tid 5902, did 117, Call has been cancelled!
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: SIP_CALL_CANCELLED
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: Fail to get Reason header at SIPPro.c, 6473#015
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro local_uri sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro remote_uri sip:<CallingNumber2>@<FreePBXIP>:5160
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro local_uri sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro remote_uri sip:<CallingNumber2>@<FreePBXIP>:5160
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 487 Request Cancelled#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK646b7a91#015#012From: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>:5160>;tag=as72a657bb#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=332911f0bdae751#015#012Call-ID: 23e589e5278429925f3b5f4951d8a273@<FreePBXIP>:5160#015#012CSeq: 102 INVITE#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 116, tid 5895, did -1, REQUEST: INVITE, Event: 25
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 116, tid 5895, did -1, RESPONSE: 487 Request Cancelled, Bye Received!, Event: 25
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: SIP_CALL_CLOSED, cid 116, did -1
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 116, call free
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 116, call free
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GetTUReportEvent:11176**********0*****#015
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK646b7a91#015#012From: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>:5160>;tag=as72a657bb#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=332911f0bdae751#015#012Call-ID: 23e589e5278429925f3b5f4951d8a273@<FreePBXIP>:5160#015#012CSeq: 102 CANCEL#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x308, Chn=0#015
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : XPhoneRelPro:20897######===>>>Line 57 LineState 0x63...#015
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SendSpecialEvent2LCM: Event=2534#015
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: _XPhoneNextState...
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: Clear Transfer, Conf and NS Flag
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: Req LCM Switch to Line 0, LineCSState 0x64
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : chn=0, AEC_switch = 1
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : MS: Chn 0 MSDspSetSendRev
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 57, event 0x8e1
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x306, Chn=0#015
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : Ti3100:HANDSET mode 
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : BSP: OpenHandset HandsetVolume :8, MicVolum 8
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012NOTIFY sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK2a35b32c#015#012Max-Forwards: 70#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Contact: <sip:<CalledNumber>@<FreePBXIP>:5160>#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 565 NOTIFY#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Subscription-State: active#015#012Event: dialog#015#012Content-Type: application/dialog-info+xml#015#012Content-Length: 211#015#012#015#012<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="463" state="full" entity="sip:<CalledNumber>@<FreePBXIP>:5160">#012<dialog id="<CalledNumber>">#012<state>confirmed</state>#012</dialog>#012</dialog-info>#012
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5903, did 5, REQUEST: NOTIFY, Event: 43
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK2a35b32c#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 565 NOTIFY#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012ACK sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK646b7a91#015#012Max-Forwards: 70#015#012From: "Elva McAllister" <sip:<CallingNumber2>@<FreePBXIP>:5160>;tag=as72a657bb#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=332911f0bdae751#015#012Contact: <sip:<CallingNumber2>@<FreePBXIP>:5160>#015#012Call-ID: 23e589e5278429925f3b5f4951d8a273@<FreePBXIP>:5160#015#012CSeq: 102 ACK#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI:MS_ZRTP_END_EVENT
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_SWITCH, Index:0
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_ONHOOK,index:57
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: 2:Call LCMSUBCallData:31390648:subdatastatistic:68
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: sencond alarm
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_ONHOOK, Index:57
2018-05-17T20:20:46-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_OFFHOOKTYPE:2

2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012BYE sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK1c1581d9#015#012Max-Forwards: 70#015#012From: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>:5160>;tag=as55945b35#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=1a613474d7035e1#015#012Call-ID: 0a3d82e041edcf0c61dd50675d173c66@<FreePBXIP>:5160#015#012CSeq: 103 BYE#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012X-Asterisk-HangupCause: Normal Clearing#015#012X-Asterisk-HangupCauseCode: 16#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK1c1581d9#015#012From: "<CallingNumber1>" <sip:<CallingNumber1>@<FreePBXIP>:5160>;tag=as55945b35#015#012To: <sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP>;tag=1a613474d7035e1#015#012Call-ID: 0a3d82e041edcf0c61dd50675d173c66@<FreePBXIP>:5160#015#012CSeq: 103 BYE#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, tid 5904, did 115, REQUEST: BYE, Event: 18
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, tid 5904, did 115, RESPONSE: 200 OK, New request received!, Event: 18
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, tid 5904, did 115, REQUEST: BYE, Event: 25
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, tid 5904, did 115, RESPONSE: 200 OK, Bye Received!, Event: 25
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: SIP_CALL_CLOSED, cid 114, did 115
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlCall, can't get call_dialog!!!
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: ActionUrlPro active_url sip:<CalledNumber>@<PhoneIP>:5060
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, call free
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 114, call free
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GetTUReportEvent:11176**********0*****#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x64, Event=0x306, Chn=0#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : XPhoneRelPro:20897######===>>>Line 0 LineState 0x64...#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL:20909========Play Busy Tone and SET timer========#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x953
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SendSpecialEvent2LCM: Event=2534#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: _XPhoneNextState...
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: Clear Transfer, Conf and NS Flag
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: There isn't any call, Release
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8f7
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SendSpecialEvent2LCM: Event=2534#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : MSDspStopMute:2077#####015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : chn=0, AEC_switch = 0
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : MS: Chn 0 MSDspStopSendRev
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8e1
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012NOTIFY sip:<CalledNumber>@<PhoneIP>:5060;transport=UDP SIP/2.0#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK025d4526#015#012Max-Forwards: 70#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Contact: <sip:<CalledNumber>@<FreePBXIP>:5160>#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 566 NOTIFY#015#012User-Agent: FPBX-13.0.194.2(13.18.0)#015#012Subscription-State: active#015#012Event: dialog#015#012Content-Type: application/dialog-info+xml#015#012Content-Length: 212#015#012#015#012<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="464" state="full" entity="sip:<CalledNumber>@<FreePBXIP>:5160">#012<dialog id="<CalledNumber>">#012<state>terminated</state>#012</dialog>#012</dialog-info>#012
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIP: aid 0, cid 0, tid 5905, did 5, REQUEST: NOTIFY, Event: 43
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : #015#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP <FreePBXIP>:5160;branch=z9hG4bK025d4526#015#012From: <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=as6e7dcd45#015#012To: "Transportation Department" <sip:<CalledNumber>@<FreePBXIP>:5160>;tag=1fbef4feefd873a#015#012Call-ID: 6c4bcf41daba18a@<PhoneIP>#015#012CSeq: 566 NOTIFY#015#012User-Agent: Sangoma S500 V2.0.4.28#015#012Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK#015#012Content-Length: 0#015#012#015#012
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : SIPPro: 12915, Release All Sip Dialog!!#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: Receive CALL_BUSY_LOCK_KEYPAD!
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI:MS_ZRTP_END_EVENT
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_REL_ALL, Index:0
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: 2:Call LCMSUBCallData:31434016:subdatastatistic:69
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x60, Event=0x91c, Chn=0#015
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: LCM Exit MenuCfg
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: Idle Softkey History,,,Menu
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : LCM: Select aid:0
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : L2C: LCM set aid 0
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_ONHOOK,index:0
2018-05-17T20:20:55-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: CALL_ONHOOK, Index:0
2018-05-17T20:20:56-06:00 <PhoneIP> [S500][<PhoneMAC>] : SYSLOG: use ram temp--------------------------------------------index 1, mode w+

2018-05-17T20:20:59-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL: State=0x60, Event=0x1007, Chn=0#015
2018-05-17T20:20:59-06:00 <PhoneIP> [S500][<PhoneMAC>] : CALL:21938=============BUSY TONE TIME OUT==============#015
2018-05-17T20:20:59-06:00 <PhoneIP> [S500][<PhoneMAC>] : CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x954
2018-05-17T20:20:59-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: Receive CALL_BUSY_UNLOCK_KEYPAD!
2018-05-17T20:20:59-06:00 <PhoneIP> [S500][<PhoneMAC>] : L2Call receive NormalReleaseEvent, release
2018-05-17T20:20:59-06:00 <PhoneIP> [S500][<PhoneMAC>] : L2Call receive NormalReleaseEvent, release
2018-05-17T20:21:00-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI:SaveCallhistoryList2Xml start!#012 
2018-05-17T20:21:00-06:00 <PhoneIP> [S500][<PhoneMAC>] : GUI: SaveCallhistoryList2Xml completed!#012

cynjut · May 18, 2018, 3:40pm

I’d probably coordinate this with the Sangoma folks through a support ticket.

Having said that, I don’t see anything that should be doing what you are describing. Can you post the /var/log/asterisk/full log of these calls so we can see what the system thinks it’s doing?

mdoupe · May 18, 2018, 6:40pm

I was afraid you’d say that. we bought them over a year ago.

Part 1

[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__DIRECTION=INBOUND") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:2] Gosub("PJSIP/<SIPTrunkProvider>-000601e5", "app-blacklist-check,s,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?blacklisted") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLED_BLACKLIST=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__FROM_DID=<CalledDID>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CDR(did)=<CalledDID>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:5] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1 ?Set(CALLERID(name)=<CallerNumber1>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:6] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__MOHCLASS=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__REVERSAL_REJECT=FALSE") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:8] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?post-reverse-charge") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (from-trunk,<CalledDID>,10)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:10] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:11] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:12] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:13] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:14] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:15] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "CallerID Entry Point") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:16] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_DIRECTION=INBOUND") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:17] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_SOURCE=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:18] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_LINKEDID=1526588342.1581745") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:19] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:20] Goto("PJSIP/<SIPTrunkProvider>-000601e5", "from-did-direct,<CalledExtension>,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (from-did-direct,<CalledExtension>,1)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledExtension>@from-did-direct:1] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?ext-local,<CalledExtension>,1:followme-check,<CalledExtension>,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (ext-local,<CalledExtension>,1)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledExtension>@ext-local:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__RINGTIMER=20") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledExtension>@ext-local:2] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "exten-vm,<CalledExtension>,<CalledExtension>,0,0,0") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:1] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "user-callerid,") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "TOUCH_MONITOR=1526588342.1581745") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "AMPUSER=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?report") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?Set(REALCALLERIDNUM=<CallerNumber1>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "AMPUSER=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?limit") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "AMPUSERCIDNAME=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?report") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:15] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Macro Depth is 2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?report2:macroerror") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:19] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__TTL=64") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-user-callerid,s,36)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:36] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(number)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:37] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(name)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:38] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?cnum") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:39] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CDR(cnam)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CDR(cnum)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:41] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CHANNEL(language)=en") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:42] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?app-check-classofservce,s,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "RingGroupMethod=none") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__EXTTOCALL=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__PICKUPMARK=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "RT=20") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Macro(vm,<CalledExtension>,DIRECTDIAL,)") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?MacroExit()") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Gosub(ext-intercom,*80<CalledExtension>,1())") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?MacroExit()") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:10] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?ChanSpy(SIP/<CalledExtension>,q)") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:11] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?MacroExit()") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:12] Gosub("PJSIP/<SIPTrunkProvider>-000601e5", "sub-record-check,s,1(exten,<CalledExtension>,dontcare)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?initialized") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__REC_STATUS=INITIALIZED") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "NOW=1526588342") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__DAY=17") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__MONTH=05") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__YEAR=2018") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__TIMESTR=20180517-141902") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__FROMEXTEN=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__MON_FMT=wav") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Recordings initialized") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ARG3=dontcare)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/<SIPTrunkProvider>-000601e5", "REC_POLICY_MODE_SAVE=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(REC_STATUS=NO)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "5?checkaction") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?sub-record-check,exten,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:1] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Exten Recording Check between <CallerNumber1> and <CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLTYPE=external") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(CALLTYPE=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLEE=dontcare") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:5] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(CALLEE=dontcare)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:6] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?callee") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,exten,11)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:11] Gosub("PJSIP/<SIPTrunkProvider>-000601e5", "recordcheck,1(dontcare,external,<CalledExtension>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Starting recording check against dontcare") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/<SIPTrunkProvider>-000601e5", "dontcare") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:12] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:13] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?macrodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-exten-vm,s,19)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:19] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?clrheader,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:20] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "dial-one,20,Ttr,<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DEXTEN=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_SOURCE=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(__EXTTOCALL=<CalledExtension>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DIALSTATUS_CW=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:5] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?screen,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:6] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?cf,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:7] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?skip1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,10)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:10] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?nodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:11] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:12] Set("PJSIP/<SIPTrunkProvider>-000601e5", "EXTHASCW=ENABLED") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:13] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?next1:cwinusebusy") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,25)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:25] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?next3:continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,27)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:27] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?nodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:28] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?dstring,1():dlocal,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DSTRING=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DEVICES=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Return()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(DEVICES=072)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "LOOPCNT=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:6] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "THISDIAL=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?zap2dahdi,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Return()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "NEWDIAL=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "LOOPCNT2=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER2=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "THISPART2=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(THISPART2=DAHDI/<CalledExtension>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "NEWDIAL=SIP/<CalledExtension>&") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER2=2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?begin2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("PJSIP/<SIPTrunkProvider>-000601e5", "THISDIAL=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?docheck") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,dstring,14)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:14] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?skipset") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:15] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DSTRING=SIP/<CalledExtension>&") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:16] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER=2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:17] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?begin") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:18] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Return()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:19] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DSTRING=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:20] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:29] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?nodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:30] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?skiptrace") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:31] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?ctset,1():ctclear,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [ctset@macro-dial-one:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DB(CALLTRACE/<CalledExtension>)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [ctset@macro-dial-one:2] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:32] Set("PJSIP/<SIPTrunkProvider>-000601e5", "D_OPTIONS=Ttr") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:33] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:34] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:35] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:36] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:37] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:38] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:39] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:40] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(CHANNEL(musicclass)=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:41] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?qwait,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:42] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CWIGNORE=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:43] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__KEEPCID=TRUE") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:44] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?usegoto,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:45] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?godial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,50)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:50] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "dialout-one-predial-hook,") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:51] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?Set(D_OPTIONS=trI)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:52] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:53] Dial("PJSIP/<SIPTrunkProvider>-000601e5", "SIP/<CalledExtension>,20,trIb(func-apply-sipheaders^s^1)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] netsock2.c: Using SIP RTP TOS bits 184
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] netsock2.c: Using SIP RTP CoS mark 6

mdoupe · May 18, 2018, 6:43pm

Part 2

[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__DIRECTION=INBOUND") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:2] Gosub("PJSIP/<SIPTrunkProvider>-000601e5", "app-blacklist-check,s,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?blacklisted") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLED_BLACKLIST=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__FROM_DID=<CalledDID>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CDR(did)=<CalledDID>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:5] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1 ?Set(CALLERID(name)=<CallerNumber1>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:6] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__MOHCLASS=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__REVERSAL_REJECT=FALSE") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:8] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?post-reverse-charge") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (from-trunk,<CalledDID>,10)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:10] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:11] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:12] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:13] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:14] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:15] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "CallerID Entry Point") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:16] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_DIRECTION=INBOUND") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:17] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_SOURCE=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:18] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_LINKEDID=1526588342.1581745") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:19] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledDID>@from-trunk:20] Goto("PJSIP/<SIPTrunkProvider>-000601e5", "from-did-direct,<CalledExtension>,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (from-did-direct,<CalledExtension>,1)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledExtension>@from-did-direct:1] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?ext-local,<CalledExtension>,1:followme-check,<CalledExtension>,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (ext-local,<CalledExtension>,1)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledExtension>@ext-local:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__RINGTIMER=20") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [<CalledExtension>@ext-local:2] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "exten-vm,<CalledExtension>,<CalledExtension>,0,0,0") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:1] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "user-callerid,") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "TOUCH_MONITOR=1526588342.1581745") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "AMPUSER=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?report") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?Set(REALCALLERIDNUM=<CallerNumber1>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "AMPUSER=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?limit") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "AMPUSERCIDNAME=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?report") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:15] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Macro Depth is 2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?report2:macroerror") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:19] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__TTL=64") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-user-callerid,s,36)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:36] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(number)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:37] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLERID(name)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:38] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?cnum") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:39] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CDR(cnam)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CDR(cnum)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:41] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CHANNEL(language)=en") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-user-callerid:42] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?app-check-classofservce,s,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "RingGroupMethod=none") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__EXTTOCALL=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__PICKUPMARK=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "RT=20") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Macro(vm,<CalledExtension>,DIRECTDIAL,)") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?MacroExit()") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Gosub(ext-intercom,*80<CalledExtension>,1())") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?MacroExit()") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:10] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?ChanSpy(SIP/<CalledExtension>,q)") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:11] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?MacroExit()") in new stack
[2018-05-17 14:19:02] WARNING[22753][C-0007e99e] chan_sip.c: This function can only be used on SIP channels.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:12] Gosub("PJSIP/<SIPTrunkProvider>-000601e5", "sub-record-check,s,1(exten,<CalledExtension>,dontcare)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?initialized") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__REC_STATUS=INITIALIZED") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "NOW=1526588342") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__DAY=17") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__MONTH=05") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__YEAR=2018") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__TIMESTR=20180517-141902") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__FROMEXTEN=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__MON_FMT=wav") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Recordings initialized") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ARG3=dontcare)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/<SIPTrunkProvider>-000601e5", "REC_POLICY_MODE_SAVE=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(REC_STATUS=NO)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "5?checkaction") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?sub-record-check,exten,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:1] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Exten Recording Check between <CallerNumber1> and <CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLTYPE=external") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(CALLTYPE=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "CALLEE=dontcare") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:5] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(CALLEE=dontcare)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:6] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?callee") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,exten,11)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:11] Gosub("PJSIP/<SIPTrunkProvider>-000601e5", "recordcheck,1(dontcare,external,<CalledExtension>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Starting recording check against dontcare") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/<SIPTrunkProvider>-000601e5", "dontcare") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [exten@sub-record-check:12] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:13] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?macrodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-exten-vm,s,19)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:19] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?clrheader,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-exten-vm:20] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "dial-one,20,Ttr,<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DEXTEN=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_SOURCE=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(__EXTTOCALL=<CalledExtension>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DIALSTATUS_CW=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:5] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?screen,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:6] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?cf,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:7] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?skip1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,10)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:10] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?nodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:11] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:12] Set("PJSIP/<SIPTrunkProvider>-000601e5", "EXTHASCW=ENABLED") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:13] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?next1:cwinusebusy") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,25)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:25] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?next3:continue") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,27)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:27] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?nodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:28] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?dstring,1():dlocal,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DSTRING=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DEVICES=<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Return()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(DEVICES=072)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "LOOPCNT=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:6] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "THISDIAL=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?zap2dahdi,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Return()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("PJSIP/<SIPTrunkProvider>-000601e5", "NEWDIAL=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("PJSIP/<SIPTrunkProvider>-000601e5", "LOOPCNT2=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER2=1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("PJSIP/<SIPTrunkProvider>-000601e5", "THISPART2=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(THISPART2=DAHDI/<CalledExtension>)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("PJSIP/<SIPTrunkProvider>-000601e5", "NEWDIAL=SIP/<CalledExtension>&") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER2=2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?begin2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("PJSIP/<SIPTrunkProvider>-000601e5", "THISDIAL=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?docheck") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,dstring,14)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:14] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?skipset") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:15] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DSTRING=SIP/<CalledExtension>&") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:16] Set("PJSIP/<SIPTrunkProvider>-000601e5", "ITER=2") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:17] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?begin") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:18] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Return()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:19] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DSTRING=SIP/<CalledExtension>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [dstring@macro-dial-one:20] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:29] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?nodial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:30] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?skiptrace") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:31] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?ctset,1():ctclear,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [ctset@macro-dial-one:1] Set("PJSIP/<SIPTrunkProvider>-000601e5", "DB(CALLTRACE/<CalledExtension>)=<CallerNumber1>") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [ctset@macro-dial-one:2] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:32] Set("PJSIP/<SIPTrunkProvider>-000601e5", "D_OPTIONS=Ttr") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:33] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:34] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:35] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:36] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:37] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:38] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:39] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:40] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(CHANNEL(musicclass)=)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:41] GosubIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?qwait,1()") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:42] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CWIGNORE=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:43] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__KEEPCID=TRUE") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:44] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?usegoto,1") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:45] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?godial") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-dial-one,s,50)
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:50] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "dialout-one-predial-hook,") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:51] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?Set(D_OPTIONS=trI)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:52] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-dial-one:53] Dial("PJSIP/<SIPTrunkProvider>-000601e5", "SIP/<CalledExtension>,20,trIb(func-apply-sipheaders^s^1)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] netsock2.c: Using SIP RTP TOS bits 184
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] netsock2.c: Using SIP RTP CoS mark 6
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] app_stack.c: SIP/<CalledExtension>-000ad185 Internal Gosub(func-apply-sipheaders,s,1) start
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("SIP/<CalledExtension>-000ad185", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("SIP/<CalledExtension>-000ad185", "Applying SIP Headers to channel") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@func-apply-sipheaders:3] Set("SIP/<CalledExtension>-000ad185", "SIPHEADERKEYS=") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@func-apply-sipheaders:4] While("SIP/<CalledExtension>-000ad185", "0") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] app_while.c: Jumping to priority 8

mdoupe · May 18, 2018, 6:43pm

Part 3

[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@func-apply-sipheaders:9] Return("SIP/<CalledExtension>-000ad185", "") in new stack
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] app_stack.c: Spawn extension (from-internal, <CalledExtension>, 1) exited non-zero on 'SIP/<CalledExtension>-000ad185'
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] app_stack.c: SIP/<CalledExtension>-000ad185 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] app_dial.c: Called SIP/<CalledExtension>
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] app_dial.c: Connected line update to PJSIP/<SIPTrunkProvider>-000601e5 prevented.
[2018-05-17 14:19:02] VERBOSE[22753][C-0007e99e] app_dial.c: SIP/<CalledExtension>-000ad185 is ringing
[2018-05-17 14:19:10] VERBOSE[22753][C-0007e99e] app_dial.c: Connected line update to PJSIP/<SIPTrunkProvider>-000601e5 prevented.
[2018-05-17 14:19:10] VERBOSE[22753][C-0007e99e] app_dial.c: SIP/<CalledExtension>-000ad185 answered PJSIP/<SIPTrunkProvider>-000601e5
[2018-05-17 14:19:10] VERBOSE[22800][C-0007e99e] bridge_channel.c: Channel SIP/<CalledExtension>-000ad185 joined 'simple_bridge' basic-bridge <ef74129a-b060-474c-93be-7d19d03e2d30>
[2018-05-17 14:19:10] VERBOSE[22753][C-0007e99e] bridge_channel.c: Channel PJSIP/<SIPTrunkProvider>-000601e5 joined 'simple_bridge' basic-bridge <ef74129a-b060-474c-93be-7d19d03e2d30>
[2018-05-17 14:20:26] VERBOSE[9149][C-0007e9af] netsock2.c: Using SIP RTP TOS bits 184
[2018-05-17 14:20:26] VERBOSE[9149][C-0007e9af] netsock2.c: Using SIP RTP CoS mark 6
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [<CalledExtension>@from-internal:1] GotoIf("SIP/<CallerNumber2>-000ad199", "1?ext-local,<CalledExtension>,1:followme-check,<CalledExtension>,1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (ext-local,<CalledExtension>,1)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [<CalledExtension>@ext-local:1] Set("SIP/<CallerNumber2>-000ad199", "__RINGTIMER=20") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [<CalledExtension>@ext-local:2] Macro("SIP/<CallerNumber2>-000ad199", "exten-vm,<CalledExtension>,<CalledExtension>,0,0,0") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:1] Macro("SIP/<CallerNumber2>-000ad199", "user-callerid,") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/<CallerNumber2>-000ad199", "TOUCH_MONITOR=1526588426.1581787") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/<CallerNumber2>-000ad199", "AMPUSER=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/<CallerNumber2>-000ad199", "0?report") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/<CallerNumber2>-000ad199", "1?Set(REALCALLERIDNUM=<CallerNumber2>)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/<CallerNumber2>-000ad199", "AMPUSER=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/<CallerNumber2>-000ad199", "0?limit") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/<CallerNumber2>-000ad199", "AMPUSERCIDNAME=<CallerName2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/<CallerNumber2>-000ad199", "0?report") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/<CallerNumber2>-000ad199", "AMPUSERCID=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/<CallerNumber2>-000ad199", "__DIAL_OPTIONS=Ttr") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/<CallerNumber2>-000ad199", "CALLERID(all)="<CallerName2>" <<CallerNumber2>>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:12] GotoIf("SIP/<CallerNumber2>-000ad199", "0?limit") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(GROUP(concurrency_limit)=<CallerNumber2>)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(CHANNEL(language)=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:15] NoOp("SIP/<CallerNumber2>-000ad199", "Macro Depth is 2") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("SIP/<CallerNumber2>-000ad199", "1?report2:macroerror") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/<CallerNumber2>-000ad199", "0?continue") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:19] Set("SIP/<CallerNumber2>-000ad199", "__TTL=64") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("SIP/<CallerNumber2>-000ad199", "1?continue") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-user-callerid,s,36)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:36] Set("SIP/<CallerNumber2>-000ad199", "CALLERID(number)=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/<CallerNumber2>-000ad199", "CALLERID(name)=<CallerName2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:38] GotoIf("SIP/<CallerNumber2>-000ad199", "0?cnum") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:39] Set("SIP/<CallerNumber2>-000ad199", "CDR(cnam)=<CallerName2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/<CallerNumber2>-000ad199", "CDR(cnum)=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/<CallerNumber2>-000ad199", "CHANNEL(language)=en") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:42] GosubIf("SIP/<CallerNumber2>-000ad199", "0?app-check-classofservce,s,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:2] Set("SIP/<CallerNumber2>-000ad199", "RingGroupMethod=none") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:3] Set("SIP/<CallerNumber2>-000ad199", "__EXTTOCALL=<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:4] Set("SIP/<CallerNumber2>-000ad199", "__PICKUPMARK=<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:5] Set("SIP/<CallerNumber2>-000ad199", "RT=20") in new stack
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Macro(vm,<CalledExtension>,DIRECTDIAL,)") in new stack
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("SIP/<CallerNumber2>-000ad199", "0?MacroExit()") in new stack
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Gosub(ext-intercom,*80<CalledExtension>,1())") in new stack
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("SIP/<CallerNumber2>-000ad199", "0?MacroExit()") in new stack
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:10] ExecIf("SIP/<CallerNumber2>-000ad199", "0?ChanSpy(SIP/<CalledExtension>,q)") in new stack
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:11] ExecIf("SIP/<CallerNumber2>-000ad199", "0?MacroExit()") in new stack
[2018-05-17 14:20:26] ERROR[23347][C-0007e9af] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:12] Gosub("SIP/<CallerNumber2>-000ad199", "sub-record-check,s,1(exten,<CalledExtension>,dontcare)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/<CallerNumber2>-000ad199", "0?initialized") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:2] Set("SIP/<CallerNumber2>-000ad199", "__REC_STATUS=INITIALIZED") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:3] Set("SIP/<CallerNumber2>-000ad199", "NOW=1526588426") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:4] Set("SIP/<CallerNumber2>-000ad199", "__DAY=17") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:5] Set("SIP/<CallerNumber2>-000ad199", "__MONTH=05") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:6] Set("SIP/<CallerNumber2>-000ad199", "__YEAR=2018") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:7] Set("SIP/<CallerNumber2>-000ad199", "__TIMESTR=20180517-142026") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:8] Set("SIP/<CallerNumber2>-000ad199", "__FROMEXTEN=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:9] Set("SIP/<CallerNumber2>-000ad199", "__MON_FMT=wav") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/<CallerNumber2>-000ad199", "Recordings initialized") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(ARG3=dontcare)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:12] Set("SIP/<CallerNumber2>-000ad199", "REC_POLICY_MODE_SAVE=") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(REC_STATUS=NO)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/<CallerNumber2>-000ad199", "5?checkaction") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/<CallerNumber2>-000ad199", "1?sub-record-check,exten,1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:1] NoOp("SIP/<CallerNumber2>-000ad199", "Exten Recording Check between <CallerNumber2> and <CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:2] Set("SIP/<CallerNumber2>-000ad199", "CALLTYPE=internal") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:3] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(CALLTYPE=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:4] Set("SIP/<CallerNumber2>-000ad199", "CALLEE=dontcare") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:5] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(CALLEE=dontcare)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:6] GotoIf("SIP/<CallerNumber2>-000ad199", "0?callee") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:7] GotoIf("SIP/<CallerNumber2>-000ad199", "1?caller") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:13] Set("SIP/<CallerNumber2>-000ad199", "RECMODE=dontcare") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:14] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(RECMODE=dontcare)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:15] ExecIf("SIP/<CallerNumber2>-000ad199", "1?Set(RECMODE=dontcare)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:16] Gosub("SIP/<CallerNumber2>-000ad199", "recordcheck,1(dontcare,internal,<CalledExtension>)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/<CallerNumber2>-000ad199", "Starting recording check against dontcare") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/<CallerNumber2>-000ad199", "dontcare") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [exten@sub-record-check:17] Return("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:13] GotoIf("SIP/<CallerNumber2>-000ad199", "1?macrodial") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-exten-vm,s,19)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:19] GosubIf("SIP/<CallerNumber2>-000ad199", "0?clrheader,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:20] Macro("SIP/<CallerNumber2>-000ad199", "dial-one,20,Ttr,<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:1] Set("SIP/<CallerNumber2>-000ad199", "DEXTEN=<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:2] Set("SIP/<CallerNumber2>-000ad199", "__CRM_SOURCE=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:3] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(__EXTTOCALL=<CalledExtension>)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:4] Set("SIP/<CallerNumber2>-000ad199", "DIALSTATUS_CW=") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:5] GosubIf("SIP/<CallerNumber2>-000ad199", "0?screen,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:6] GosubIf("SIP/<CallerNumber2>-000ad199", "0?cf,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:7] GotoIf("SIP/<CallerNumber2>-000ad199", "1?skip1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-dial-one,s,10)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:10] GotoIf("SIP/<CallerNumber2>-000ad199", "0?nodial") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:11] GotoIf("SIP/<CallerNumber2>-000ad199", "0?continue") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:12] Set("SIP/<CallerNumber2>-000ad199", "EXTHASCW=ENABLED") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:13] GotoIf("SIP/<CallerNumber2>-000ad199", "0?next1:cwinusebusy") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-dial-one,s,25)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:25] GotoIf("SIP/<CallerNumber2>-000ad199", "0?next3:continue") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-dial-one,s,27)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:27] GotoIf("SIP/<CallerNumber2>-000ad199", "0?nodial") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:28] GosubIf("SIP/<CallerNumber2>-000ad199", "1?dstring,1():dlocal,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:1] Set("SIP/<CallerNumber2>-000ad199", "DSTRING=") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:2] Set("SIP/<CallerNumber2>-000ad199", "DEVICES=<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Return()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(DEVICES=072)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:5] Set("SIP/<CallerNumber2>-000ad199", "LOOPCNT=1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:6] Set("SIP/<CallerNumber2>-000ad199", "ITER=1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:7] Set("SIP/<CallerNumber2>-000ad199", "THISDIAL=SIP/<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("SIP/<CallerNumber2>-000ad199", "1?zap2dahdi,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Return()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("SIP/<CallerNumber2>-000ad199", "NEWDIAL=") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("SIP/<CallerNumber2>-000ad199", "LOOPCNT2=1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("SIP/<CallerNumber2>-000ad199", "ITER2=1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("SIP/<CallerNumber2>-000ad199", "THISPART2=SIP/<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(THISPART2=DAHDI/<CalledExtension>)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("SIP/<CallerNumber2>-000ad199", "NEWDIAL=SIP/<CalledExtension>&") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("SIP/<CallerNumber2>-000ad199", "ITER2=2") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/<CallerNumber2>-000ad199", "0?begin2") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("SIP/<CallerNumber2>-000ad199", "THISDIAL=SIP/<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("SIP/<CallerNumber2>-000ad199", "1?docheck") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-dial-one,dstring,14)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:14] GotoIf("SIP/<CallerNumber2>-000ad199", "0?skipset") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:15] Set("SIP/<CallerNumber2>-000ad199", "DSTRING=SIP/<CalledExtension>&") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:16] Set("SIP/<CallerNumber2>-000ad199", "ITER=2") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:17] GotoIf("SIP/<CallerNumber2>-000ad199", "0?begin") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:18] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Return()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:19] Set("SIP/<CallerNumber2>-000ad199", "DSTRING=SIP/<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [dstring@macro-dial-one:20] Return("SIP/<CallerNumber2>-000ad199", "") in new stack

mdoupe · May 18, 2018, 6:45pm

Part 4

[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:29] GotoIf("SIP/<CallerNumber2>-000ad199", "0?nodial") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:30] GotoIf("SIP/<CallerNumber2>-000ad199", "0?skiptrace") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:31] GosubIf("SIP/<CallerNumber2>-000ad199", "1?ctset,1():ctclear,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [ctset@macro-dial-one:1] Set("SIP/<CallerNumber2>-000ad199", "DB(CALLTRACE/<CalledExtension>)=<CallerNumber2>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [ctset@macro-dial-one:2] Return("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:32] Set("SIP/<CallerNumber2>-000ad199", "D_OPTIONS=Ttr") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:33] NoOp("SIP/<CallerNumber2>-000ad199", "Blind Transfer: , Attended Transfer: , User: <CallerNumber2>, Alert Info: ") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:34] ExecIf("SIP/<CallerNumber2>-000ad199", "1?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:35] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:36] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(ALERT_INFO=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:37] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:38] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:39] GosubIf("SIP/<CallerNumber2>-000ad199", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:40] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(CHANNEL(musicclass)=)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:41] GosubIf("SIP/<CallerNumber2>-000ad199", "0?qwait,1()") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:42] Set("SIP/<CallerNumber2>-000ad199", "__CWIGNORE=") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:43] Set("SIP/<CallerNumber2>-000ad199", "__KEEPCID=TRUE") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:44] GotoIf("SIP/<CallerNumber2>-000ad199", "0?usegoto,1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:45] GotoIf("SIP/<CallerNumber2>-000ad199", "0?godial") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:46] Gosub("SIP/<CallerNumber2>-000ad199", "sub-presencestate-display,s,1(<CalledExtension>)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@sub-presencestate-display:1] Goto("SIP/<CallerNumber2>-000ad199", "state-available,1") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (sub-presencestate-display,state-available,1)
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [state-available@sub-presencestate-display:1] Set("SIP/<CallerNumber2>-000ad199", "PRESENCESTATE_DISPLAY=(Available)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [state-available@sub-presencestate-display:2] Return("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:47] Set("SIP/<CallerNumber2>-000ad199", "CONNECTEDLINE(name,i)=<CalledName>(Available)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:48] Set("SIP/<CallerNumber2>-000ad199", "CONNECTEDLINE(num)=<CalledExtension>") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:49] Set("SIP/<CallerNumber2>-000ad199", "D_OPTIONS=TtrI") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:50] Macro("SIP/<CallerNumber2>-000ad199", "dialout-one-predial-hook,") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:51] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(D_OPTIONS=trII)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:52] NoOp("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:53] Dial("SIP/<CallerNumber2>-000ad199", "SIP/<CalledExtension>,20,TtrIb(func-apply-sipheaders^s^1)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] netsock2.c: Using SIP RTP TOS bits 184
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] netsock2.c: Using SIP RTP CoS mark 6
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] app_stack.c: SIP/<CalledExtension>-000ad19a Internal Gosub(func-apply-sipheaders,s,1) start
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("SIP/<CalledExtension>-000ad19a", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("SIP/<CalledExtension>-000ad19a", "Applying SIP Headers to channel") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@func-apply-sipheaders:3] Set("SIP/<CalledExtension>-000ad19a", "SIPHEADERKEYS=") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@func-apply-sipheaders:4] While("SIP/<CalledExtension>-000ad19a", "0") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] app_while.c: Jumping to priority 8
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@func-apply-sipheaders:9] Return("SIP/<CalledExtension>-000ad19a", "") in new stack
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] app_stack.c: Spawn extension (from-internal, <CalledExtension>, 1) exited non-zero on 'SIP/<CalledExtension>-000ad19a'
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] app_stack.c: SIP/<CalledExtension>-000ad19a Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] app_dial.c: Called SIP/<CalledExtension>
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] app_dial.c: Connected line update to SIP/<CallerNumber2>-000ad199 prevented.
[2018-05-17 14:20:26] VERBOSE[23347][C-0007e9af] app_dial.c: SIP/<CalledExtension>-000ad19a is ringing
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] app_dial.c: Nobody picked up in 20000 ms
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:54] ExecIf("SIP/<CallerNumber2>-000ad199", "0?MacroExit()") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:55] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(DIALSTATUS=)") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:56] GosubIf("SIP/<CallerNumber2>-000ad199", "0?s-NOANSWER,1()") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-dial-one:57] MacroExit("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:21] Set("SIP/<CallerNumber2>-000ad199", "SV_DIALSTATUS=NOANSWER") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:22] GosubIf("SIP/<CallerNumber2>-000ad199", "0?docfu,1()") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:23] GosubIf("SIP/<CallerNumber2>-000ad199", "0?docfb,1()") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:24] Set("SIP/<CallerNumber2>-000ad199", "DIALSTATUS=NOANSWER") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:25] ExecIf("SIP/<CallerNumber2>-000ad199", "0?MacroExit()") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:26] GotoIf("SIP/<CallerNumber2>-000ad199", "0?s-NOANSWER,1") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-exten-vm:27] Macro("SIP/<CallerNumber2>-000ad199", "vm,<CalledExtension>,NOANSWER,") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-vm:1] Macro("SIP/<CallerNumber2>-000ad199", "user-callerid,SKIPTTL") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/<CallerNumber2>-000ad199", "TOUCH_MONITOR=1526588426.1581787") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/<CallerNumber2>-000ad199", "AMPUSER=<CallerNumber2>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/<CallerNumber2>-000ad199", "15?report") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:15] NoOp("SIP/<CallerNumber2>-000ad199", "Macro Depth is 3") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("SIP/<CallerNumber2>-000ad199", "1?report2:macroerror") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/<CallerNumber2>-000ad199", "1?continue") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-user-callerid,s,36)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:36] Set("SIP/<CallerNumber2>-000ad199", "CALLERID(number)=<CallerNumber2>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/<CallerNumber2>-000ad199", "CALLERID(name)=<CallerName2>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:38] GotoIf("SIP/<CallerNumber2>-000ad199", "0?cnum") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:39] Set("SIP/<CallerNumber2>-000ad199", "CDR(cnam)=<CallerName2>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/<CallerNumber2>-000ad199", "CDR(cnum)=<CallerNumber2>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/<CallerNumber2>-000ad199", "CHANNEL(language)=en") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-user-callerid:42] GosubIf("SIP/<CallerNumber2>-000ad199", "0?app-check-classofservce,s,1()") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-vm:2] Set("SIP/<CallerNumber2>-000ad199", "VMGAIN=g(12)") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-vm:3] Macro("SIP/<CallerNumber2>-000ad199", "blkvm-check,") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-blkvm-check:1] Set("SIP/<CallerNumber2>-000ad199", "GOSUB_RETVAL=") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-blkvm-check:2] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-blkvm-check:3] MacroExit("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-vm:4] GotoIf("SIP/<CallerNumber2>-000ad199", "1?vmx,1") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-vm,vmx,1)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:1] Set("SIP/<CallerNumber2>-000ad199", "__EXTTOCALL=<CalledExtension>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:2] Set("SIP/<CallerNumber2>-000ad199", "__CRM_VOICEMAIL=<CalledExtension>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:3] Set("SIP/<CallerNumber2>-000ad199", "MEXTEN=<CalledExtension>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:4] Set("SIP/<CallerNumber2>-000ad199", "MMODE=NOANSWER") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:5] Set("SIP/<CallerNumber2>-000ad199", "RETVM=") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:6] Set("SIP/<CallerNumber2>-000ad199", "MODE=unavail") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:7] Macro("SIP/<CallerNumber2>-000ad199", "get-vmcontext,<CalledExtension>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-get-vmcontext:1] Set("SIP/<CallerNumber2>-000ad199", "VMCONTEXT=default") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("SIP/<CallerNumber2>-000ad199", "0?200:300") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:8] Set("SIP/<CallerNumber2>-000ad199", "MODE=unavail") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:9] NoOp("SIP/<CallerNumber2>-000ad199", "MODE IS: unavail") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:10] GotoIf("SIP/<CallerNumber2>-000ad199", "1?chknomsg") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-vm,vmx,12)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:12] GotoIf("SIP/<CallerNumber2>-000ad199", "0?s-NOANSWER,1") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:13] GotoIf("SIP/<CallerNumber2>-000ad199", "1?notdirect") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-vm,vmx,15)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:15] NoOp("SIP/<CallerNumber2>-000ad199", "Checking if ext <CalledExtension> is enabled: ") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [vmx@macro-vm:16] GotoIf("SIP/<CallerNumber2>-000ad199", "1?s-NOANSWER,1") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-vm,s-NOANSWER,1)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s-NOANSWER@macro-vm:1] Macro("SIP/<CallerNumber2>-000ad199", "get-vmcontext,<CalledExtension>") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-get-vmcontext:1] Set("SIP/<CallerNumber2>-000ad199", "VMCONTEXT=default") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("SIP/<CallerNumber2>-000ad199", "0?200:300") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s-NOANSWER@macro-vm:2] VoiceMail("SIP/<CallerNumber2>-000ad199", "<CalledExtension>@default,ug(12)") in new stack
[2018-05-17 14:20:46] VERBOSE[23347][C-0007e9af] file.c: <SIP/<CallerNumber2>-000ad199> Playing '/var/spool/asterisk/voicemail/default/<CalledExtension>/unavail.slin' (language 'en')
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] bridge_channel.c: Channel PJSIP/<SIPTrunkProvider>-000601e5 left 'simple_bridge' basic-bridge <ef74129a-b060-474c-93be-7d19d03e2d30>
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] bridge_channel.c: Channel SIP/<CalledExtension>-000ad185 left 'simple_bridge' basic-bridge <ef74129a-b060-474c-93be-7d19d03e2d30>
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] app_macro.c: Spawn extension (macro-dial-one, s, 53) exited non-zero on 'PJSIP/<SIPTrunkProvider>-000601e5' in macro 'dial-one'
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] app_stack.c: SIP/<CalledExtension>-000ad185 Internal Gosub(crm-hangup,s,1) start
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] pbx.c: Executing [s@crm-hangup:1] NoOp("SIP/<CalledExtension>-000ad185", "Sending Hangup to CRM") in new stack
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] pbx.c: Executing [s@crm-hangup:2] NoOp("SIP/<CalledExtension>-000ad185", "HANGUP CAUSE: 16") in new stack
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] pbx.c: Executing [s@crm-hangup:3] ExecIf("SIP/<CalledExtension>-000ad185", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] pbx.c: Executing [s@crm-hangup:4] NoOp("SIP/<CalledExtension>-000ad185", "MASTER CHANNEL: 1526588342.1581746 = 1526588342.1581745") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] app_macro.c: Spawn extension (macro-exten-vm, s, 20) exited non-zero on 'PJSIP/<SIPTrunkProvider>-000601e5' in macro 'exten-vm'
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Spawn extension (ext-local, <CalledExtension>, 2) exited non-zero on 'PJSIP/<SIPTrunkProvider>-000601e5'
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] pbx.c: Executing [s@crm-hangup:5] GotoIf("SIP/<CalledExtension>-000ad185", "1?return") in new stack
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] pbx_builtins.c: Goto (crm-hangup,s,8)
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] pbx.c: Executing [s@crm-hangup:8] Return("SIP/<CalledExtension>-000ad185", "") in new stack
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] app_stack.c: Spawn extension (from-internal, , 1) exited non-zero on 'SIP/<CalledExtension>-000ad185'
[2018-05-17 14:20:55] VERBOSE[22800][C-0007e99e] app_stack.c: SIP/<CalledExtension>-000ad185 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/<SIPTrunkProvider>-000601e5", "hangupcall,") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "1?theend") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(CDR(recordingfile)=)") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/<SIPTrunkProvider>-000601e5' in macro 'hangupcall'
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/<SIPTrunkProvider>-000601e5'
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] app_stack.c: PJSIP/<SIPTrunkProvider>-000601e5 Internal Gosub(crm-hangup,s,1) start
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "Sending Hangup to CRM") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "HANGUP CAUSE: 16") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/<SIPTrunkProvider>-000601e5", "MASTER CHANNEL: 1526588342.1581745 = 1526588342.1581745") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/<SIPTrunkProvider>-000601e5", "0?return") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:6] Set("PJSIP/<SIPTrunkProvider>-000601e5", "__CRM_HANGUP=1") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:7] AGI("PJSIP/<SIPTrunkProvider>-000601e5", "sangomacrm.agi") in new stack
[2018-05-17 14:20:55] VERBOSE[22753][C-0007e99e] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-05-17 14:20:56] VERBOSE[22753][C-0007e99e] res_agi.c: <PJSIP/<SIPTrunkProvider>-000601e5>AGI Script sangomacrm.agi completed, returning 0
[2018-05-17 14:20:56] VERBOSE[22753][C-0007e99e] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/<SIPTrunkProvider>-000601e5", "") in new stack
[2018-05-17 14:20:56] VERBOSE[22753][C-0007e99e] app_stack.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/<SIPTrunkProvider>-000601e5'
[2018-05-17 14:20:56] VERBOSE[22753][C-0007e99e] app_stack.c: PJSIP/<SIPTrunkProvider>-000601e5 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-05-17 14:21:07] VERBOSE[23347][C-0007e9af] file.c: <SIP/<CallerNumber2>-000ad199> Playing 'vm-intro.ulaw' (language 'en')
[2018-05-17 14:21:12] VERBOSE[23347][C-0007e9af] file.c: <SIP/<CallerNumber2>-000ad199> Playing 'beep.ulaw' (language 'en')
[2018-05-17 14:21:13] VERBOSE[23347][C-0007e9af] app_voicemail.c: Recording the message
[2018-05-17 14:21:13] VERBOSE[23347][C-0007e9af] app.c: x=0, open writing:  /var/spool/asterisk/voicemail/default/<CalledExtension>/tmp/ykH6Rk format: wav, 0x7f4bc756e300
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] app.c: User hung up
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] config.c: Parsing '/var/spool/asterisk/voicemail/default/<CalledExtension>/INBOX/msg0000.txt': Found
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] config.c: Parsing '/var/spool/asterisk/voicemail/default/<CalledExtension>/INBOX/msg0000.txt': Found
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] config.c: Parsing '/var/spool/asterisk/voicemail/default/<CalledExtension>/INBOX/msg0000.txt': Found
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] app_macro.c: Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'SIP/<CallerNumber2>-000ad199' in macro 'vm'
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] app_macro.c: Spawn extension (macro-exten-vm, s, 27) exited non-zero on 'SIP/<CallerNumber2>-000ad199' in macro 'exten-vm'
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] pbx.c: Spawn extension (ext-local, <CalledExtension>, 2) exited non-zero on 'SIP/<CallerNumber2>-000ad199'
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] pbx.c: Executing [h@ext-local:1] Macro("SIP/<CallerNumber2>-000ad199", "hangupcall,") in new stack
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/<CallerNumber2>-000ad199", "1?theend") in new stack
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/<CallerNumber2>-000ad199", "0?Set(CDR(recordingfile)=)") in new stack
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/<CallerNumber2>-000ad199", "") in new stack
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/<CallerNumber2>-000ad199' in macro 'hangupcall'
[2018-05-17 14:21:33] VERBOSE[23347][C-0007e9af] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/<CallerNumber2>-000ad199'

tonyclewis · May 18, 2018, 8:59pm

Phones get free support from support.sangoma.com under the phone section

system · May 18, 2019, 8:59pm

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.