rendered paste body -- Accepting AUTHENTICATED call from 192.168.10.101: > requested format = g729, > requested prefs = (g729), > actual format = g729, > host prefs = (g729), > priority = caller[Dec 5 01:05:12] DEBUG[7429]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '0390118400'[Dec 5 01:05:12] DEBUG[7429]: pbx.c:1828 pbx_extension_helper: Launching 'NoOp' -- Executing [131166@from-holly-v2:1] NoOp("IAX2/holly-v2-g729-1", "CALLERID: 0390118400") in new stack[Dec 5 01:05:12] DEBUG[7429]: pbx.c:1828 pbx_extension_helper: Launching 'NoOp' -- Executing [131166@from-holly-v2:2] NoOp("IAX2/holly-v2-g729-1", "CALLINGPRES: 3") in new stack[Dec 5 01:05:12] DEBUG[7429]: pbx.c:1828 pbx_extension_helper: Launching 'NoOp' -- Executing [131166@from-holly-v2:3] NoOp("IAX2/holly-v2-g729-1", "DIALEDPEERNUMBER: ") in new stack[Dec 5 01:05:12] DEBUG[7429]: pbx.c:1828 pbx_extension_helper: Launching 'Goto' -- Executing [131166@from-holly-v2:4] Goto("IAX2/holly-v2-g729-1", "terminate-pri|131166|1") in new stack -- Goto (terminate-pri,131166,1)[Dec 5 01:05:12] DEBUG[7429]: pbx.c:1828 pbx_extension_helper: Launching 'Dial' -- Executing [131166@terminate-pri:1] Dial("IAX2/holly-v2-g729-1", "ZAP/g1/131166|240") in new stack[Dec 5 01:05:12] DEBUG[7429]: chan_zap.c:7846 zt_request: Using channel 1[Dec 5 01:05:12] DEBUG[7429]: rtp.c:1578 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything-- Making new call for cr 32772 -- Requested transfer capability: 0x00 - SPEECH> [ 00 01 48 48 08 02 00 04 05 04 03 80 90 a3 18 03 a9 83 81 6c 0c 00 83 30 33 39 30 31 31 38 34 30 30 70 07 80 31 33 31 31 36 36 74 09 00 01 8f 33 34 30 33 34 30 a1 ]> Informational frame:> SAPI: 00 C/R: 0 EA: 0> TEI: 000 EA: 1> N(S): 036 0: 0> N(R): 036 P: 0> 50 bytes of data-- Restarting T203 counterStopping T_203 timerStarting T_200 timer> Protocol Discriminator: Q.931 (8) len=50> Call Ref: len= 2 (reference 4/0x4) (Originator)> Message type: SETUP (5)> [04 03 80 90 a3]> Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)> Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)> Ext: 1 User information layer 1: A-Law (35)> [18 03 a9 83 81]> Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0> ChanSel: Reserved> Ext: 1 Coding: 0 Number Specified Channel Type: 3> Ext: 1 Channel: 1 ]> [6c 0c 00 83 30 33 39 30 31 31 38 34 30 30]> Calling Number (len=14) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0)> Presentation: Presentation allowed of network provided number (3) '0390118400' ]> [70 07 80 31 33 31 31 36 36]> Called Number (len= 9) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '131166' ]> [74 09 00 01 8f 33 34 30 33 34 30]> Redirecting Number (len=11) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0)> Ext: 0 Presentation: Presentation permitted, user number passed network screening (1)> Ext: 1 Reason: Forwarded unconditionally (15) '340340' ]> [a1]> Sending Complete (len= 1)q931.c:2881 q931_setup: call 32772 on channel 1 enters state 1 (Call Initiated)[Dec 5 01:05:12] DEBUG[7429]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 -- Called g1/131166[Dec 5 01:05:12] DEBUG[6346]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1[Dec 5 01:05:12] DEBUG[6346]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use)[Dec 5 01:05:12] DEBUG[7429]: channel.c:3042 set_format: Set channel Zap/1-1 to read format g729[Dec 5 01:05:12] DEBUG[7429]: channel.c:3042 set_format: Set channel IAX2/holly-v2-g729-1 to write format g729[Dec 5 01:05:12] DEBUG[7429]: channel.c:3042 set_format: Set channel IAX2/holly-v2-g729-1 to read format slin[Dec 5 01:05:12] DEBUG[7429]: channel.c:3042 set_format: Set channel Zap/1-1 to write format slin< [ 00 01 01 4a ]< Supervisory frame:< SAPI: 00 C/R: 0 EA: 0< TEI: 000 EA: 1< Zero: 0 S: 0 01: 1 [ RR (receive ready) ]< N(R): 037 P/F: 0< 0 bytes of data-- ACKing all packets from 35 to (but not including) 37-- ACKing packet 36, new txqueue is -1 (-1 means empty)-- Since there was nothing left, stopping T200 counter-- Nothing left, starting T203 counter-- Restarting T203 counter< [ 02 01 48 4a 08 02 80 04 02 18 03 a9 83 81 ]< Informational frame:< SAPI: 00 C/R: 1 EA: 0< TEI: 000 EA: 1< N(S): 036 0: 0< N(R): 037 P: 0< 10 bytes of data-- ACKing all packets from 36 to (but not including) 37-- Since there was nothing left, stopping T200 counter-- Stopping T203 counter since we got an ACK-- Nothing left, starting T203 counter< Protocol Discriminator: Q.931 (8) len=10< Call Ref: len= 2 (reference 4/0x4) (Terminator)< Message type: CALL PROCEEDING (2)< [18 03 a9 83 81]< Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0< ChanSel: Reserved< Ext: 1 Coding: 0 Number Specified Channel Type: 3< Ext: 1 Channel: 1 ]-- Processing IE 24 (cs0, Channel Identification)q931.c:3428 q931_receive: call 32772 on channel 1 enters state 3 (Outgoing call Proceeding)Sending Receiver Ready (37)> [ 02 01 01 4a ]> Supervisory frame:> SAPI: 00 C/R: 1 EA: 0> TEI: 000 EA: 1> Zero: 0 S: 0 01: 1 [ RR (receive ready) ]> N(R): 037 P/F: 0> 0 bytes of data-- Restarting T203 counter-- Restarting T203 counter[Dec 5 01:05:12] DEBUG[6351]: chan_zap.c:8985 pri_dchannel: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1 -- Zap/1-1 is proceeding passing it to IAX2/holly-v2-g729-1[Dec 5 01:05:12] DEBUG[7429]: rtp.c:1495 ast_rtp_early_bridge: Channel 'IAX2/holly-v2-g729-1' has no RTP, not doing anythingT203 counter expired, sending RR and scheduling T203 againSending Receiver Ready (37)> [ 00 01 01 4b ]> Supervisory frame:> SAPI: 00 C/R: 0 EA: 0> TEI: 000 EA: 1> Zero: 0 S: 0 01: 1 [ RR (receive ready) ]> N(R): 037 P/F: 1> 0 bytes of data-- Restarting T203 counter< [ 00 01 01 4b ]< Supervisory frame:< SAPI: 00 C/R: 0 EA: 0< TEI: 000 EA: 1< Zero: 0 S: 0 01: 1 [ RR (receive ready) ]< N(R): 037 P/F: 1< 0 bytes of data-- ACKing all packets from 36 to (but not including) 37-- Since there was nothing left, stopping T200 counter-- Stopping T203 counter since we got an ACK-- Nothing left, starting T203 counter-- Got RR response to our frame-- Restarting T203 counter[Dec 5 01:05:12] DEBUG[6358]: chan_iax2.c:7129 socket_process: Ooh, voice format changed to 256< [ 02 01 4a 4a 08 02 80 04 03 1e 02 80 88 ]< Informational frame:< SAPI: 00 C/R: 1 EA: 0< TEI: 000 EA: 1< N(S): 037 0: 0< N(R): 037 P: 0< 9 bytes of data-- ACKing all packets from 36 to (but not including) 37-- Since there was nothing left, stopping T200 counter-- Stopping T203 counter since we got an ACK-- Nothing left, starting T203 counter< Protocol Discriminator: Q.931 (8) len=9< Call Ref: len= 2 (reference 4/0x4) (Terminator)< Message type: PROGRESS (3)< [1e 02 80 88]< Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: User (0)< Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]-- Processing IE 30 (cs0, Progress Indicator)Sending Receiver Ready (38)> [ 02 01 01 4c ]> Supervisory frame:> SAPI: 00 C/R: 1 EA: 0> TEI: 000 EA: 1> Zero: 0 S: 0 01: 1 [ RR (receive ready) ]> N(R): 038 P/F: 0> 0 bytes of data-- Restarting T203 counter-- Restarting T203 counter[Dec 5 01:05:12] DEBUG[6351]: chan_zap.c:8959 pri_dchannel: Queuing frame from PRI_EVENT_PROGRESS on channel 0/1 span 1 -- Zap/1-1 is making progress passing it to IAX2/holly-v2-g729-1[Dec 5 01:05:12] DEBUG[7429]: rtp.c:1495 ast_rtp_early_bridge: Channel 'IAX2/holly-v2-g729-1' has no RTP, not doing anything[Dec 5 01:05:16] DEBUG[6356]: chan_iax2.c:7469 socket_process: Immediately destroying 1, having received hangup[Dec 5 01:05:16] DEBUG[7429]: rtp.c:1495 ast_rtp_early_bridge: Channel 'IAX2/holly-v2-g729-1' has no RTP, not doing anything[Dec 5 01:05:16] DEBUG[7429]: channel.c:1765 ast_hangup: Hanging up channel 'Zap/1-1'[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:2422 zt_hangup: zt_hangup(Zap/1-1)[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:2971 zt_setoption: Set option AUDIO MODE, value: ON(1) on Zap/1-1[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:2456 zt_hangup: Hangup: channel: 1 index = 0, normal = 10, callwait = -1, thirdcall = -1[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:2610 zt_hangup: Not yet hungup... Calling hangup once with icause, and clearing callNEW_HANGUP DEBUG: Calling q931_hangup, ourstate Outgoing call Proceeding, peerstate Incoming Call Proceedingq931.c:2764 q931_disconnect: call 32772 on channel 1 enters state 11 (Disconnect Request)> [ 00 01 4a 4c 08 02 00 04 45 08 02 81 90 ]> Informational frame:> SAPI: 00 C/R: 0 EA: 0> TEI: 000 EA: 1> N(S): 037 0: 0> N(R): 038 P: 0> 9 bytes of data-- Restarting T203 counterStopping T_203 timerStarting T_200 timer> Protocol Discriminator: Q.931 (8) len=9> Call Ref: len= 2 (reference 4/0x4) (Originator)> Message type: DISCONNECT (69)> [08 02 81 90]> Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)> Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ][Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:1472 zt_disable_ec: disabled echo cancellation on channel 1[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:2886 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:1408 update_conf: Updated conferencing on 1, with 0 conference users[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:2967 zt_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/1-1[Dec 5 01:05:16] DEBUG[7429]: chan_zap.c:1472 zt_disable_ec: disabled echo cancellation on channel 1 -- Hungup 'Zap/1-1'[Dec 5 01:05:16] DEBUG[7429]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1[Dec 5 01:05:16] DEBUG[6346]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1[Dec 5 01:05:16] DEBUG[6346]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown)[Dec 5 01:05:16] DEBUG[7429]: cdr_pgsql.c:132 pgsql_log: cdr_pgsql: inserting a CDR record.[Dec 5 01:05:16] DEBUG[7429]: cdr_pgsql.c:141 pgsql_log: cdr_pgsql: SQL command executed: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-12-05 01:05:12','0390118400','0390118400','s','from-zaptel-port1', 'Zap/1-1','','','',4,0,'NO ANSWER',3,'','1196777112.5','')< [ 00 01 01 4c ]< Supervisory frame:< SAPI: 00 C/R: 0 EA: 0< TEI: 000 EA: 1< Zero: 0 S: 0 01: 1 [ RR (receive ready) ]< N(R): 038 P/F: 0< 0 bytes of data-- ACKing all packets from 36 to (but not including) 38-- ACKing packet 37, new txqueue is -1 (-1 means empty)-- Since there was nothing left, stopping T200 counter-- Nothing left, starting T203 counter-- Restarting T203 counter[Dec 5 01:05:16] DEBUG[7429]: app_dial.c:1711 dial_exec_full: Exiting with DIALSTATUS=CANCEL.[Dec 5 01:05:16] DEBUG[7429]: pbx.c:2435 __ast_pbx_run: Spawn extension (terminate-pri,131166,1) exited non-zero on 'IAX2/holly-v2-g729-1' == Spawn extension (terminate-pri, 131166, 1) exited non-zero on 'IAX2/holly-v2-g729-1'[Dec 5 01:05:16] DEBUG[7429]: channel.c:1546 ast_softhangup_nolock: Soft-Hanging up channel 'IAX2/holly-v2-g729-1'[Dec 5 01:05:16] DEBUG[7429]: channel.c:1765 ast_hangup: Hanging up channel 'IAX2/holly-v2-g729-1'[Dec 5 01:05:16] DEBUG[7429]: chan_iax2.c:3182 iax2_hangup: We're hanging up IAX2/holly-v2-g729-1 now...[Dec 5 01:05:16] DEBUG[7429]: chan_iax2.c:3197 iax2_hangup: Really destroying IAX2/holly-v2-g729-1 now... -- Hungup 'IAX2/holly-v2-g729-1'[Dec 5 01:05:16] DEBUG[7429]: devicestate.c:304 __ast_device_state_changed_