here it is, complete log with: core set debug 3
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“SIP/5xxxx-b77054a0”, “1?check”) in new stack
x:49] VERBOSE[4343] logger.c: – Goto (macro-record-enable,s,4)
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Function result is '20120930-144549’
x:49] DEBUG[4343] pbx.c: Launching 'AGI’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-record-enable:4] AGI(“SIP/5xxxx-b77054a0”, “recordingcheck|20120930-144549|1349019949.12”) in new stack
x:49] VERBOSE[4343] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
x:49] VERBOSE[4343] logger.c: recordingcheck|20120930-144549|1349019949.12: Outbound recording enabled.
x:49] VERBOSE[4343] logger.c: recordingcheck|20120930-144549|1349019949.12: CALLFILENAME=OUT5xxxx-20120930-144549-1349019949.12
x:49] VERBOSE[4343] logger.c: – AGI Script recordingcheck completed, returning 0
x:49] DEBUG[4343] app_macro.c: Executed application: AGI
x:49] DEBUG[4343] pbx.c: Launching 'MixMonitor’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-record-enable:999] MixMonitor(“SIP/5xxxx-b77054a0”, “OUT5xxxx-20120930-144549-1349019949.12.wav||”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: MixMonitor
x:49] DEBUG[4343] pbx.c: Launching 'Macro’
x:49] VERBOSE[4343] logger.c: – Executing [1xxxxxx@from-internal:4] Macro(“SIP/5xxxx-b77054a0”, “dialout-trunk|2|1xxxxxx||”) in new stack
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/5xxxx-b77054a0 - state 4 (Invalid)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer 5xxxx
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/5xxxx - state 2 (In use)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer 5xxxx
x:49] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DND5xxxx
x:49] DEBUG[2872] db.c: Unable to find key ‘DND5xxxx’ in family 'CustomDevstate’
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/5xxxx-b77054a0’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/5xxxx’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/5xxxx-b77054a0”, “DIAL_TRUNK=2”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] db.c: Unable to find key ‘5xxxx/pinless’ in family 'AMPUSER’
x:49] DEBUG[4343] func_db.c: DB: AMPUSER/5xxxx/pinless not found in database.
x:49] DEBUG[4343] pbx.c: Function result is ''
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'GosubIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/5xxxx-b77054a0”, “0?sub-pincheck|s|1”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: GosubIf
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] db.c: Unable to find key ‘5xxxx/pinless’ in family 'AMPUSER’
x:49] DEBUG[4343] func_db.c: DB: AMPUSER/5xxxx/pinless not found in database.
x:49] DEBUG[4343] pbx.c: Function result is ''
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'GotoIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/5xxxx-b77054a0”, “0?disabletrunk|1”) in new stack
x:49] DEBUG[4343] pbx.c: Not taking any branch
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/5xxxx-b77054a0”, “DIAL_NUMBER=1xxxxxx”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/5xxxx-b77054a0”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/5xxxx-b77054a0”, “OUTBOUND_GROUP=OUT_2”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Launching 'GotoIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/5xxxx-b77054a0”, “1?nomax”) in new stack
x:49] VERBOSE[4343] logger.c: – Goto (macro-dialout-trunk,s,9)
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'GotoIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/5xxxx-b77054a0”, “0?skipoutcid”) in new stack
x:49] DEBUG[4343] pbx.c: Not taking any branch
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/5xxxx-b77054a0”, “DIAL_TRUNK_OPTIONS=”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Launching 'Macro’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/5xxxx-b77054a0”, “outbound-callerid|2”) in new stack
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'ExecIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/5xxxx-b77054a0”, “0|SetCallerPres|”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: ExecIf
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Function result is '5xxxx’
x:49] DEBUG[4343] pbx.c: Launching 'ExecIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/5xxxx-b77054a0”, “0|Set|REALCALLERIDNUM=5xxxx”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: ExecIf
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Function result is '5xxxx’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Launching 'GotoIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/5xxxx-b77054a0”, “1?normcid”) in new stack
x:49] VERBOSE[4343] logger.c: – Goto (macro-outbound-callerid,s,6)
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Function result is ''
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/5xxxx-b77054a0”, “USEROUTCID=”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] db.c: Unable to find key ‘5xxxx/emergency_cid’ in family 'DEVICE’
x:49] DEBUG[4343] func_db.c: DB: DEVICE/5xxxx/emergency_cid not found in database.
x:49] DEBUG[4343] pbx.c: Function result is ''
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/5xxxx-b77054a0”, “EMERGENCYCID=”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/5xxxx-b77054a0”, “TRUNKOUTCID=xxxxxxx”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Launching 'GotoIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/5xxxx-b77054a0”, “1?trunkcid”) in new stack
x:49] VERBOSE[4343] logger.c: – Goto (macro-outbound-callerid,s,12)
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Launching 'ExecIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:12] ExecIf(“SIP/5xxxx-b77054a0”, “1|Set|CALLERID(all)=xxxxxxx”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: ExecIf
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] app_macro.c: Last app: Set|CALLERID(all)=xxxxxxx
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'ExecIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:13] ExecIf(“SIP/5xxxx-b77054a0”, “0|Set|CALLERID(all)=”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: ExecIf
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Function result is ''
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'ExecIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/5xxxx-b77054a0”, “0|SetCallerPres|prohib_passed_screen”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: ExecIf
x:49] DEBUG[4343] pbx.c: Function result is ''
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] app_macro.c: Executed application: Macro
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Launching 'ExecIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:12] ExecIf(“SIP/5xxxx-b77054a0”, “1|AGI|fixlocalprefix”) in new stack
x:49] VERBOSE[4343] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
x:49] VERBOSE[4345] logger.c: == Begin MixMonitor Recording SIP/5xxxx-b77054a0
x:49] VERBOSE[4343] logger.c: == fixlocalprefix: Dialpattern 00+. matched. 1xxxxxx -> 001xxxxxx
x:49] VERBOSE[4343] logger.c: – AGI Script fixlocalprefix completed, returning 0
x:49] DEBUG[4343] app_macro.c: Executed application: ExecIf
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] app_macro.c: Last app: AGI|fixlocalprefix
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/5xxxx-b77054a0”, “OUTNUM=001xxxxxx”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Function result is 'SIP/trunk’
x:49] DEBUG[4343] pbx.c: Launching 'Set’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/5xxxx-b77054a0”, “custom=SIP/trunk”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Set
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'ExecIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/5xxxx-b77054a0”, “0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: ExecIf
x:49] DEBUG[4343] pbx.c: Expression result is '1’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'Macro’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:16] Macro(“SIP/5xxxx-b77054a0”, “dialout-trunk-predial-hook|”) in new stack
x:49] DEBUG[4343] pbx.c: Launching 'MacroExit’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/5xxxx-b77054a0”, “”) in new stack
x:49] DEBUG[4343] app_macro.c: Executed application: Macro
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'GotoIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:17] GotoIf(“SIP/5xxxx-b77054a0”, “0?bypass|1”) in new stack
x:49] DEBUG[4343] pbx.c: Not taking any branch
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Expression result is '0’
x:49] DEBUG[4343] pbx.c: Launching 'GotoIf’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/5xxxx-b77054a0”, “0?customtrunk”) in new stack
x:49] DEBUG[4343] pbx.c: Not taking any branch
x:49] DEBUG[4343] app_macro.c: Executed application: GotoIf
x:49] DEBUG[4343] pbx.c: Launching 'Dial’
x:49] VERBOSE[4343] logger.c: – Executing [s@macro-dialout-trunk:19] Dial(“SIP/5xxxx-b77054a0”, “SIP/trunk/001xxxxxx|300|”) in new stack
x:49] DEBUG[4343] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
x:49] DEBUG[4343] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
x:49] DEBUG[4343] chan_sip.c: Setting NAT on RTP to Off
x:49] DEBUG[4343] chan_sip.c: *** Our native formats are 0x8 (alaw)
x:49] DEBUG[4343] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
x:49] DEBUG[4343] chan_sip.c: *** Our capabilities are 0x8 (alaw)
x:49] DEBUG[4343] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
x:49] DEBUG[4343] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw)
x:49] DEBUG[4343] chan_sip.c: This channel will not be able to handle video.
x:49] DEBUG[4343] channel.c: Not copying variable MACRO_DEPTH.
…
x:49] DEBUG[4343] channel.c: Not copying variable SIPURI.
x:49] DEBUG[4343] chan_sip.c: Outgoing Call for 001xxxxxx
x:49] DEBUG[4343] chan_sip.c: Updating call counter for outgoing call
x:49] DEBUG[4343] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
x:49] DEBUG[4343] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False
x:49] DEBUG[4343] chan_sip.c: ** Our prefcodec: 0x4 (ulaw)
x:49] DEBUG[4343] chan_sip.c: – Done with adding codecs to SDP
x:49] DEBUG[4343] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
x:49] VERBOSE[4343] logger.c: – Called trunk/001xxxxxx
x:49] DEBUG[4343] channel.c: Set channel SIP/trunk-097b5e40 to read format ulaw
x:49] DEBUG[4343] channel.c: Set channel SIP/5xxxx-b77054a0 to read format alaw
x:49] DEBUG[2877] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘2c074c643cbe912063acea186a7faf49@10.55.11.58’ Request 102: Found
x:49] DEBUG[2877] chan_sip.c: Setting NAT on RTP to Off
x:49] DEBUG[2877] chan_sip.c: Setting NAT on VRTP to Off
x:49] DEBUG[2877] chan_sip.c: Allocating new SIP dialog for 22ef7f00000113ce00012837000055f0@127.0.0.1 - INVITE (With RTP)
x:49] DEBUG[2877] chan_sip.c: Setting NAT on RTP to Off
x:49] DEBUG[2877] chan_sip.c: Setting NAT on VRTP to Off
x:49] DEBUG[2877] chan_sip.c: T38 state changed to 0 on channel
x:49] DEBUG[2877] chan_sip.c: We’re settling with these formats: 0x8 (alaw)
x:49] DEBUG[2877] chan_sip.c: Checking SIP call limits for device
x:49] DEBUG[2877] chan_sip.c: Updating call counter for incoming call
x:49] DEBUG[2877] chan_sip.c: *** Our native formats are 0x8 (alaw) [Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer trunk
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/trunk - state 1 (Not in use)
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer 5xxxx
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/5xxxx - state 1 (Not in use)
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer 5xxxx
x:49] DEBUG[2877] chan_sip.c: *** Joint capabilities are 0x8 (alaw)
x:49] DEBUG[2877] chan_sip.c: *** Our capabilities are 0x8 (alaw)
x:49] DEBUG[2877] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
x:49] DEBUG[2877] chan_sip.c: This channel will not be able to handle video.
x:49] DEBUG[2877] chan_sip.c: build_route: Contact hop: "xxxxxxx"sip:xxxxxxx@xx.xx.xx.xx:xxxxxxx;transport=udp
x:49] DEBUG[2877] chan_sip.c: SIP/xxxxxxx-b77033d0: New call is still down… Trying…
x:49] DEBUG[2877] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxxxxx-b77033d0
x:49] DEBUG[2877] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxxxxx
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer xxxxxxx-b77033d0
x:49] DEBUG[4347] pbx.c: Launching ‘Dial’
x:49] VERBOSE[4347] logger.c: – Executing [107081xxxex@trunk:1] Dial(“SIP/xxxxxxx-b77033d0”, “SIP/xxxex”) in new stack
x:49] DEBUG[4347] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
x:49] DEBUG[4347] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
x:49] DEBUG[4347] chan_sip.c: Setting NAT on RTP to On
x:49] DEBUG[4347] chan_sip.c: Setting NAT on VRTP to On
x:49] DEBUG[4347] chan_sip.c: *** Our native formats are 0x280004 (ulaw|h263|h264)
x:49] DEBUG[4347] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
x:49] DEBUG[4347] chan_sip.c: *** Our capabilities are 0x28000c (ulaw|alaw|h263|h264)
x:49] DEBUG[4347] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
x:49] DEBUG[4347] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw)
x:49] DEBUG[4347] chan_sip.c: This channel will not be able to handle video.
x:49] DEBUG[4347] channel.c: Not copying variable SIPCALLID.
x:49] DEBUG[4347] channel.c: Not copying variable SIPDOMAIN.
x:49] DEBUG[4347] channel.c: Not copying variable SIPURI.
x:49] DEBUG[4347] chan_sip.c: Outgoing Call for xxxex
x:49] DEBUG[4347] chan_sip.c: Updating call counter for outgoing call
x:49] DEBUG[4347] chan_sip.c: Call to peer ‘xxxex’ is 1 out of 50
x:49] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex
x:49] DEBUG[4347] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
x:49] DEBUG[4347] chan_sip.c: ** Our capability: 0x28000c (ulaw|alaw|h263|h264) Video flag: False
x:49] DEBUG[4347] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
x:49] DEBUG[4347] chan_sip.c: This call needs video offers!
x:49] DEBUG[4347] chan_sip.c: – Done with adding codecs to SDP
x:49] DEBUG[4347] chan_sip.c: Done building SDP. Settling with this capability: 0x28000c (ulaw|alaw|h263|h264)
x:49] VERBOSE[4347] logger.c: – Called xxxex
x:49] DEBUG[4347] channel.c: Set channel SIP/xxxex-0983e368 to read format alaw
x:49] DEBUG[4347] channel.c: Set channel SIP/xxxxxxx-b77033d0 to read format ulaw
x:49] DEBUG[2877] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '67c7829e33533a787c4125c5018a894a@xx.xx.xx.xx’ Request 102: Found
x:49] DEBUG[2877] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '67c7829e33533a787c4125c5018a894a@xx.xx.xx.xx’ Request 102: Found
x:49] DEBUG[2877] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex-0983e368
x:49] DEBUG[2877] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex
x:49] VERBOSE[4347] logger.c: – SIP/xxxex-0983e368 is ringing
x:49] DEBUG[2877] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘2c074c643cbe912063acea186a7faf49@10.55.11.58’ Request 102: Found
x:49] DEBUG[2877] devicestate.c: Notification of state change to be queued on device/channel SIP/trunk-097b5e40
x:49] DEBUG[2877] devicestate.c: Notification of state change to be queued on device/channel SIP/trunk
x:49] VERBOSE[4343] logger.c: – SIP/trunk-097b5e40 is ringing
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/xxxxxxx-b77033d0 - state 4 (Invalid)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer xxxxxxx
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/xxxxxxx - state 4 (Invalid)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex - state 6 (Ringing)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:49] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DNDxxxex
x:49] DEBUG[2872] db.c: Unable to find key ‘DNDxxxex’ in family ‘CustomDevstate’
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex-0983e368
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/xxxxxxx-b77033d0’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/xxxxxxx’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex’ changed to state ‘6’ (Ringing) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex-0983e368 - state 4 (Invalid)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex - state 6 (Ringing)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:49] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DNDxxxex
x:49] DEBUG[2872] db.c: Unable to find key ‘DNDxxxex’ in family ‘CustomDevstate’
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer trunk-097b5e40
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex-0983e368’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex’ changed to state ‘6’ (Ringing) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/trunk-097b5e40 - state 4 (Invalid)
x:49] DEBUG[2872] chan_sip.c: Checking device state for peer trunk
x:49] DEBUG[2872] devicestate.c: Changing state for SIP/trunk - state 1 (Not in use)
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/trunk-097b5e40’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:49] DEBUG[2890] app_queue.c: Device ‘SIP/trunk’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2877] chan_sip.c: Acked pending invite 102
x:55] DEBUG[2877] chan_sip.c: Stopping retransmission on '67c7829e33533a787c4125c5018a894a@xx.xx.xx.xx’ of Request 102: Match Found
x:55] DEBUG[2877] chan_sip.c: T38 state changed to 0 on channel SIP/xxxex-0983e368
x:55] DEBUG[2877] chan_sip.c: We’re settling with these formats: 0xc (ulaw|alaw)
x:55] DEBUG[2877] chan_sip.c: Updating call counter for outgoing call
x:55] DEBUG[2877] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex
x:55] DEBUG[2877] chan_sip.c: build_route: Contact hop: sip:xxxex@192.168.0.163:xxxxxxx
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex - state 2 (In use)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:55] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DNDxxxex
x:55] DEBUG[2872] db.c: Unable to find key ‘DNDxxxex’ in family ‘CustomDevstate’
x:55] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex-0983e368
x:55] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex
x:55] VERBOSE[4347] logger.c: – SIP/xxxex-0983e368 answered SIP/xxxxxxx-b77033d0
x:55] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxxxxx-b77033d0
x:55] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxxxxx
x:55] DEBUG[4347] chan_sip.c: SIP answering channel: SIP/xxxxxxx-b77033d0
x:55] DEBUG[4347] chan_sip.c: Setting framing from config on incoming call
x:55] DEBUG[4347] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True
x:55] DEBUG[4347] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
x:55] DEBUG[4347] chan_sip.c: – Done with adding codecs to SDP
x:55] DEBUG[4347] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex-0983e368
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex-0983e368 - state 4 (Invalid)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex - state 2 (In use)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
x:55] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DNDxxxex
x:55] DEBUG[2872] db.c: Unable to find key ‘DNDxxxex’ in family ‘CustomDevstate’
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer xxxxxxx-b77033d0
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex-0983e368’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/xxxxxxx-b77033d0 - state 4 (Invalid)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer xxxxxxx
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/xxxxxxx - state 4 (Invalid)
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/xxxxxxx-b77033d0’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/xxxxxxx’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2877] chan_sip.c: Stopping retransmission on ‘22ef7f00000113ce00012837000055f0@127.0.0.1’ of Response 2: Match Found
x:55] DEBUG[2877] chan_sip.c: Acked pending invite 102
x:55] DEBUG[2877] chan_sip.c: Stopping retransmission on ‘2c074c643cbe912063acea186a7faf49@10.55.11.58’ of Request 102: Match Found
x:55] DEBUG[2877] chan_sip.c: T38 state changed to 0 on channel SIP/trunk-097b5e40
x:55] DEBUG[2877] chan_sip.c: We’re settling with these formats: 0x8 (alaw)
x:55] DEBUG[2877] chan_sip.c: Updating call counter for outgoing call
x:55] DEBUG[2877] chan_sip.c: build_route: Contact hop: sip:001xxxxxx@xx.xx.xx.xx:xxxxxxx;transport=udp
x:55] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/trunk-097b5e40
x:55] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/trunk
x:55] VERBOSE[4343] logger.c: – SIP/trunk-097b5e40 answered SIP/5xxxx-b77054a0
x:55] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/5xxxx-b77054a0
x:55] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/5xxxx
x:55] DEBUG[4343] chan_sip.c: SIP answering channel: SIP/5xxxx-b77054a0
x:55] DEBUG[4343] chan_sip.c: Setting framing from config on incoming call
x:55] DEBUG[4343] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True
x:55] DEBUG[4343] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
x:55] DEBUG[4343] chan_sip.c: – Done with adding codecs to SDP
x:55] DEBUG[4343] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer trunk-097b5e40
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/trunk-097b5e40 - state 4 (Invalid)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer trunk
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/trunk - state 1 (Not in use)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer 5xxxx-b77054a0
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/trunk-097b5e40’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/trunk’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/5xxxx-b77054a0 - state 4 (Invalid)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer 5xxxx
x:55] DEBUG[2872] devicestate.c: Changing state for SIP/5xxxx - state 2 (In use)
x:55] DEBUG[2872] chan_sip.c: Checking device state for peer 5xxxx
x:55] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DND5xxxx
x:55] DEBUG[2872] db.c: Unable to find key ‘DND5xxxx’ in family ‘CustomDevstate’
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/5xxxx-b77054a0’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2890] app_queue.c: Device ‘SIP/5xxxx’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
x:55] DEBUG[2877] chan_sip.c: T38 state changed to 0 on channel SIP/xxxxxxx-b77033d0
x:55] DEBUG[2877] chan_sip.c: We’re settling with these formats: 0x8 (alaw)
x:55] DEBUG[2877] chan_sip.c: SIP/xxxxxxx-b77033d0: This call is UP…
x:55] DEBUG[2877] chan_sip.c: Setting framing from config on incoming call
x:55] DEBUG[2877] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True
x:55] DEBUG[2877] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
x:55] DEBUG[2877] chan_sip.c: – Done with adding codecs to SDP
x:55] DEBUG[2877] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
x:55] DEBUG[2877] chan_sip.c: Stopping retransmission on ‘22ef7f00000113ce00012837000055f0@127.0.0.1’ of Response 3: Match Found
x:55] DEBUG[4347] chan_sip.c: Oooh, format changed to 8
x:55] DEBUG[4347] channel.c: Set channel SIP/xxxex-0983e368 to read format alaw
x:55] DEBUG[4347] channel.c: Set channel SIP/xxxex-0983e368 to write format ulaw
x:55] DEBUG[4347] rtp.c: Ooh, format changed from unknown to alaw
x:55] DEBUG[4347] rtp.c: Created smoother: format: 8 ms: 20 len: 160
x:55] DEBUG[4343] rtp.c: Ooh, format changed from unknown to ulaw
x:55] DEBUG[4343] rtp.c: Created smoother: format: 4 ms: 20 len: 160
x:55] DEBUG[4345] audiohook.c: Read factory 0x97cf288 was pretty quick last time, waiting for them.
…
[Sep 30 14:46:03] DEBUG[4345] audiohook.c: Read factory 0x97cf288 was pretty quick last time, waiting for them.
…
[Sep 30 14:46:04] DEBUG[4345] audiohook.c: Read factory 0x97cf288 was pretty quick last time, waiting for them.
[Sep 30 14:46:04] DEBUG[2877] chan_sip.c: Setting SIP_ALREADYGONE on dialog 67c7829e33533a787c4125c5018a894a@xx.xx.xx.xx
[Sep 30 14:46:04] DEBUG[2877] chan_sip.c: Received bye, issuing owner hangup
[Sep 30 14:46:04] DEBUG[4347] channel.c: Didn’t get a frame from channel: SIP/xxxex-0983e368
[Sep 30 14:46:04] DEBUG[4347] channel.c: Bridge stops bridging channels SIP/xxxxxxx-b77033d0 and SIP/xxxex-0983e368
[Sep 30 14:46:04] DEBUG[4347] channel.c: Hanging up channel ‘SIP/xxxex-0983e368’
[Sep 30 14:46:04] DEBUG[4347] chan_sip.c: Hangup call SIP/xxxex-0983e368, SIP callid 67c7829e33533a787c4125c5018a894a@xx.xx.xx.xx)
[Sep 30 14:46:04] DEBUG[4347] chan_sip.c: Updating call counter for outgoing call
[Sep 30 14:46:04] DEBUG[4347] chan_sip.c: Call to peer ‘xxxex’ removed from call limit 50
[Sep 30 14:46:04] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex
[Sep 30 14:46:04] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex-0983e368
[Sep 30 14:46:04] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxex
[Sep 30 14:46:04] DEBUG[4347] rtp.c: Channel ‘’ has no RTP, not doing anything
[Sep 30 14:46:04] DEBUG[4347] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Sep 30 14:46:04] DEBUG[4347] pbx.c: Spawn extension (trunk,107081xxxex,1) exited non-zero on ‘SIP/xxxxxxx-b77033d0’
[Sep 30 14:46:04] VERBOSE[4347] logger.c: == Spawn extension (trunk, 107081xxxex, 1) exited non-zero on ‘SIP/xxxxxxx-b77033d0’
[Sep 30 14:46:04] DEBUG[4347] channel.c: Soft-Hanging up channel ‘SIP/xxxxxxx-b77033d0’
[Sep 30 14:46:04] DEBUG[4347] channel.c: Hanging up channel ‘SIP/xxxxxxx-b77033d0’
[Sep 30 14:46:04] DEBUG[4347] chan_sip.c: Hangup call SIP/xxxxxxx-b77033d0, SIP callid 22ef7f00000113ce00012837000055f0@127.0.0.1)
[Sep 30 14:46:04] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxxxxx-b77033d0
[Sep 30 14:46:04] DEBUG[4347] devicestate.c: Notification of state change to be queued on device/channel SIP/xxxxxxx
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex - state 1 (Not in use)
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DNDxxxex
[Sep 30 14:46:04] DEBUG[2872] db.c: Unable to find key ‘DNDxxxex’ in family ‘CustomDevstate’
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex-0983e368
[Sep 30 14:46:04] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Sep 30 14:46:04] DEBUG[4347] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Sep 30 14:46:04] DEBUG[4347] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES (‘2012-09-30 14:45:49’,’“xxxxxxx” ‘,‘xxxxxxx’,‘107081xxxex’,‘trunk’, ‘SIP/xxxxxxx-b77033d0’,‘SIP/xxxex-0983e368’,‘Dial’,‘SIP/xxxex’,15,9,‘ANSWERED’,3,’’,‘1349019949.14’,’’)
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex-0983e368 - state 4 (Invalid)
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/xxxex - state 1 (Not in use)
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer xxxex
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Checking if I can find provider for “Custom” - number: DNDxxxex
[Sep 30 14:46:04] DEBUG[2872] db.c: Unable to find key ‘DNDxxxex’ in family ‘CustomDevstate’
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer xxxxxxx-b77033d0
[Sep 30 14:46:04] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex-0983e368’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[Sep 30 14:46:04] DEBUG[2890] app_queue.c: Device ‘SIP/xxxex’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/xxxxxxx-b77033d0 - state 4 (Invalid)
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer xxxxxxx
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/xxxxxxx - state 4 (Invalid)
[Sep 30 14:46:04] DEBUG[2890] app_queue.c: Device ‘SIP/xxxxxxx-b77033d0’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[Sep 30 14:46:04] DEBUG[2890] app_queue.c: Device ‘SIP/xxxxxxx’ changed to state ‘4’ (Invalid) but we don’t care because they’re not a member of any queue.
[Sep 30 14:46:04] DEBUG[2877] chan_sip.c: Stopping retransmission on ‘22ef7f00000113ce00012837000055f0@127.0.0.1’ of Request 102: Match Found
[Sep 30 14:46:04] DEBUG[2877] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2c074c643cbe912063acea186a7faf49@10.55.11.58
[Sep 30 14:46:04] DEBUG[2877] chan_sip.c: Received bye, issuing owner hangup
[Sep 30 14:46:04] DEBUG[4343] channel.c: Didn’t get a frame from channel: SIP/trunk-097b5e40
[Sep 30 14:46:04] DEBUG[4343] channel.c: Bridge stops bridging channels SIP/5xxxx-b77054a0 and SIP/trunk-097b5e40
[Sep 30 14:46:04] DEBUG[4343] channel.c: Hanging up channel ‘SIP/trunk-097b5e40’
[Sep 30 14:46:04] DEBUG[4343] chan_sip.c: Hangup call SIP/trunk-097b5e40, SIP callid 2c074c643cbe912063acea186a7faf49@10.55.11.58)
[Sep 30 14:46:04] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/trunk-097b5e40
[Sep 30 14:46:04] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/trunk
[Sep 30 14:46:04] DEBUG[4343] rtp.c: Channel ‘’ has no RTP, not doing anything
[Sep 30 14:46:04] DEBUG[4343] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Sep 30 14:46:04] DEBUG[4343] app_macro.c: Spawn extension (macro-dialout-trunk,s,19) exited non-zero on ‘SIP/5xxxx-b77054a0’ in macro ‘dialout-trunk’
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Spawn extension (macro-dialout-trunk,s,19) exited non-zero on ‘SIP/5xxxx-b77054a0’
[Sep 30 14:46:04] VERBOSE[4343] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on ‘SIP/5xxxx-b77054a0’
[Sep 30 14:46:04] DEBUG[4343] channel.c: Soft-Hanging up channel ‘SIP/5xxxx-b77054a0’
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Launching ‘Macro’
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/5xxxx-b77054a0”, “hangupcall|”) in new stack
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Expression result is ‘1’
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Launching ‘GotoIf’
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/5xxxx-b77054a0”, “1?skiprg”) in new stack
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Goto (macro-hangupcall,s,4)
[Sep 30 14:46:04] DEBUG[4343] app_macro.c: Executed application: GotoIf
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Expression result is ‘1’
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Launching ‘GotoIf’
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“SIP/5xxxx-b77054a0”, “1?skipblkvm”) in new stack
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Goto (macro-hangupcall,s,7)
[Sep 30 14:46:04] DEBUG[4343] app_macro.c: Executed application: GotoIf
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Expression result is ‘1’
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Launching ‘GotoIf’
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“SIP/5xxxx-b77054a0”, “1?theend”) in new stack
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Goto (macro-hangupcall,s,9)
[Sep 30 14:46:04] DEBUG[4343] app_macro.c: Executed application: GotoIf
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Launching ‘Hangup’
[Sep 30 14:46:04] VERBOSE[4343] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“SIP/5xxxx-b77054a0”, “”) in new stack
[Sep 30 14:46:04] DEBUG[4343] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on ‘SIP/5xxxx-b77054a0’ in macro ‘hangupcall’
[Sep 30 14:46:04] DEBUG[4343] pbx.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on ‘SIP/5xxxx-b77054a0’
[Sep 30 14:46:04] VERBOSE[4343] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/5xxxx-b77054a0’
[Sep 30 14:46:04] DEBUG[4343] channel.c: Hanging up channel ‘SIP/5xxxx-b77054a0’
[Sep 30 14:46:04] DEBUG[4343] chan_sip.c: Hangup call SIP/5xxxx-b77054a0, SIP callid etwqtouaezujtoq@svgtm01)
[Sep 30 14:46:04] DEBUG[4343] chan_sip.c: Updating call counter for incoming call
[Sep 30 14:46:04] DEBUG[4343] chan_sip.c: Call from peer ‘5xxxx’ removed from call limit 50
[Sep 30 14:46:04] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/5xxxx
[Sep 30 14:46:04] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/5xxxx-b77054a0
[Sep 30 14:46:04] DEBUG[4343] devicestate.c: Notification of state change to be queued on device/channel SIP/5xxxx
[Sep 30 14:46:04] DEBUG[2872] chan_sip.c: Checking device state for peer trunk-097b5e40
[Sep 30 14:46:04] VERBOSE[4345] logger.c: == End MixMonitor Recording SIP/5xxxx-b77054a0
[Sep 30 14:46:04] DEBUG[4343] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Sep 30 14:46:04] DEBUG[4343] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES (‘2012-09-30 14:45:49’,‘xxxxxxx’,‘xxxxxxx’,‘1xxxxxx’,‘from-internal’, ‘SIP/5xxxx-b77054a0’,‘SIP/trunk-097b5e40’,‘Dial’,‘SIP/trunk/001xxxxxx|300|’,15,9,‘ANSWERED’,3,’’,‘1349019949.12’,’’)
[Sep 30 14:46:04] DEBUG[2872] devicestate.c: Changing state for SIP/trunk-097b5e40 - state 4 (Invalid)