-- 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 counter
Stopping T_203 timer
Starting 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 anything
T203 counter expired, sending RR and scheduling T203 again
Sending 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 call
NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Outgoing call  Proceeding, peerstate Incoming Call Proceeding
q931.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 counter
Stopping T_203 timer
Starting 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_