rendered paste body[root@pbx asterisk]# grep "Jul 20 11:16" full
Jul 20 11:16:04 DEBUG[3049] chan_sip.c: Stopping retransmission on '203c54e963f0238817428068632990b7@172.17.170.253' of Request 102: Match Found
Jul 20 11:16:38 VERBOSE[3008] logger.c: -- Remote UNIX connection
Jul 20 11:16:47 VERBOSE[3527] logger.c: -- Remote UNIX connection disconnected
Jul 20 11:16:50 VERBOSE[3008] logger.c: -- Remote UNIX connection
Jul 20 11:16:55 DEBUG[3049] chan_sip.c: Stopping retransmission on '1917262950d071d46fef93185f62bdac@172.17.170.253' of Request 102: Match Found
Jul 20 11:16:55 DEBUG[3049] chan_sip.c: Stopping retransmission on '694dec2d46cd07f0388449650c51d894@172.17.170.253' of Request 102: Match Found
Jul 20 11:16:55 DEBUG[3049] chan_sip.c: Stopping retransmission on '7ff501bd38c5ee0955e3dc4b5a1be035@172.17.170.253' of Request 102: Match Found
Jul 20 11:16:55 DEBUG[3049] chan_sip.c: Stopping retransmission on '3663d6aa25d946fa2dcc21053c85767a@172.17.170.253' of Request 102: Match Found
Jul 20 11:16:55 DEBUG[3049] chan_sip.c: Stopping retransmission on '240ad5f57e52d0130790790a21b9a2c0@172.17.170.253' of Request 102: Match Found
Jul 20 11:16:55 DEBUG[3049] chan_sip.c: Stopping retransmission on '0bf71afa6593743d33aa63d444e7f8a8@172.17.170.253' of Request 102: Match Found
Jul 20 11:16:02 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:02 DEBUG[3049] chan_sip.c: Stopping retransmission on 'f430a5fc4cda69e8@172.17.170.150' of Response 13021: Match Found
Jul 20 11:16:02 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:02 DEBUG[3049] chan_sip.c: Checking SIP call limits for device 325
Jul 20 11:16:02 DEBUG[3049] chan_sip.c: build_route: Contact hop: <sip:325@172.17.170.150:36408>
Jul 20 11:16:02 DEBUG[3010] channel.c: Avoiding initial deadlock for 'SIP/325-b7905e28'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Macro("SIP/325-b7905e28", "dialout-trunk|1|96784806||") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK=1") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "_NODEST=") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_NUMBER=96784806") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "ROUTE_PASSWD=") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=tr") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?noauth") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-dialout-trunk,s,8)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "GROUP()=OUT_1") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Macro("SIP/325-b7905e28", "user-callerid|SKIPTTL") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is 'device'
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '325'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "user-callerid: device 325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Noop
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Not taking any branch
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?start") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Not taking any branch
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '325'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: NoOp
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '325'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSER=325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is 'Ryan Williams'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSERCIDNAME=Ryan Williams") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Not taking any branch
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=Ryan Williams <325>") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '325'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "TTL: ARG1: SKIPTTL") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Noop
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?continue") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-user-callerid,s,21)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '"Ryan Williams" <325>'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Using CallerID "Ryan Williams" <325>") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: NoOp
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Macro
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '325'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Macro("SIP/325-b7905e28", "record-enable|325|OUT") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '0'
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?2:4") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-record-enable,s,4)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "recordingcheck|20070720-111602|1184894162.214") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 20 11:16:02 VERBOSE[5743] logger.c: recordingcheck|20070720-111602|1184894162.214: Outbound recording not enabled
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- AGI Script recordingcheck completed, returning 0
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "No recording needed") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Noop
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Macro
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?skipoutcid") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Not taking any branch
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Macro("SIP/325-b7905e28", "outbound-callerid|1") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?start") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-outbound-callerid,s,3)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: NoOp
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?normcid") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-outbound-callerid,s,9)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '243200325'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "USEROUTCID=243200325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] db.c: Unable to find key '325/emergency_cid' in family 'DEVICE'
Jul 20 11:16:02 DEBUG[5743] func_db.c: DB: DEVICE/325/emergency_cid not found in database.
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is ''
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "EMERGENCYCID=") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "TRUNKOUTCID=243200300") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?trunkcid") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-outbound-callerid,s,16)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?usercid") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Not taking any branch
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200300") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Not taking any branch
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200325") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is ''
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?report:hidecid") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-outbound-callerid,s,22)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is '"" <243200325>'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "CallerID set to "" <243200325>") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: NoOp
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Macro
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?nomax") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Goto (macro-dialout-trunk,s,16)
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "fixlocalprefix") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jul 20 11:16:02 VERBOSE[5743] logger.c: == fixlocalprefix: Dialpattern XXXXXXXX matched. 96784806 -> 96784806
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "OUTNUM=96784806") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Function result is 'ZAP/g0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Set("SIP/325-b7905e28", "custom=ZAP/g0") in new stack
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: Set
Jul 20 11:16:02 DEBUG[5743] pbx.c: Expression result is '0'
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?customtrunk") in new stack
Jul 20 11:16:02 DEBUG[5743] pbx.c: Not taking any branch
Jul 20 11:16:02 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Executing Dial("SIP/325-b7905e28", "ZAP/g0/96784806|300|") in new stack
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Requested transfer capability: 0x00 - SPEECH
Jul 20 11:16:02 VERBOSE[5743] logger.c:
Jul 20 11:16:02 VERBOSE[5743] logger.c:
Jul 20 11:16:02 VERBOSE[5743] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:02 VERBOSE[5743] logger.c: > N(S): 007 0: 0
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Restarting T203 counter
Jul 20 11:16:02 VERBOSE[5743] logger.c: Stopping T_203 timer
Jul 20 11:16:02 VERBOSE[5743] logger.c: Starting T_200 timer
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Protocol Discriminator: Q.931 (8) len=40
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Call Ref: len= 2 (reference 28/0x1C) (Originator)
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Message type: SETUP (5)
Jul 20 11:16:02 VERBOSE[5743] logger.c: > [04 03 80 90 a3]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Jul 20 11:16:02 VERBOSE[5743] logger.c: > [18 03 a9 83 81]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:02 VERBOSE[5743] logger.c: > ChanSel: Reserved
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Ext: 1 Channel: 1 ]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > [6c 0b 21 80 32 34 33 32 30 30 33 32 35]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Calling Number (len=13) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Presentation: Presentation permitted, user number not screened (0) '243200325' ]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > [70 09 c1 39 36 37 38 34 38 30 36]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Called Number (len=11) [ Ext: 1 TON: Subscriber Number (4) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '96784806' ]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > [a1]
Jul 20 11:16:02 VERBOSE[5743] logger.c: > Sending Complete (len= 1)
Jul 20 11:16:02 VERBOSE[5743] logger.c: -- Called g0/96784806
Jul 20 11:16:02 VERBOSE[3127] logger.c:
Jul 20 11:16:02 VERBOSE[3127] logger.c:
Jul 20 11:16:02 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:02 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:02 VERBOSE[3127] logger.c: -- ACKing all packets from 6 to (but not including) 8
Jul 20 11:16:02 VERBOSE[3127] logger.c: -- ACKing packet 7, new txqueue is -1 (-1 means empty)
Jul 20 11:16:02 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:02 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:02 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:03 VERBOSE[3127] logger.c:
Jul 20 11:16:03 VERBOSE[3127] logger.c:
Jul 20 11:16:03 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:03 VERBOSE[3127] logger.c: < N(S): 012 0: 0
Jul 20 11:16:03 VERBOSE[3127] logger.c: -- ACKing all packets from 7 to (but not including) 8
Jul 20 11:16:03 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:03 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:03 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:03 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Jul 20 11:16:03 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 28/0x1C) (Terminator)
Jul 20 11:16:03 VERBOSE[3127] logger.c: < Message type: CALL PROCEEDING (2)
Jul 20 11:16:03 VERBOSE[3127] logger.c: < [18 03 a9 83 81]
Jul 20 11:16:03 VERBOSE[3127] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:03 VERBOSE[3127] logger.c: < ChanSel: Reserved
Jul 20 11:16:03 VERBOSE[3127] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:03 VERBOSE[3127] logger.c: < Ext: 1 Channel: 1 ]
Jul 20 11:16:03 VERBOSE[3127] logger.c: Sending Receiver Ready (13)
Jul 20 11:16:03 VERBOSE[3127] logger.c:
Jul 20 11:16:03 VERBOSE[3127] logger.c:
Jul 20 11:16:03 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:03 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:03 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:03 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:03 DEBUG[3127] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
Jul 20 11:16:03 VERBOSE[5743] logger.c: -- Zap/1-1 is proceeding passing it to SIP/325-b7905e28
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:04 VERBOSE[3127] logger.c: < N(S): 013 0: 0
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- ACKing all packets from 7 to (but not including) 8
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 28/0x1C) (Terminator)
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Message type: DISCONNECT (69)
Jul 20 11:16:04 VERBOSE[3127] logger.c: < [08 02 80 91]
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0)
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:04 VERBOSE[3127] logger.c: < [1e 02 82 88]
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]
Jul 20 11:16:04 VERBOSE[3127] logger.c: Sending Receiver Ready (14)
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:04 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Channel 0/1, span 1 got hangup request
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Zap/1-1 is busy
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Jul 20 11:16:04 VERBOSE[5743] logger.c:
Jul 20 11:16:04 VERBOSE[5743] logger.c:
Jul 20 11:16:04 VERBOSE[5743] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:04 VERBOSE[5743] logger.c: > N(S): 008 0: 0
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Restarting T203 counter
Jul 20 11:16:04 VERBOSE[5743] logger.c: Stopping T_203 timer
Jul 20 11:16:04 VERBOSE[5743] logger.c: Starting T_200 timer
Jul 20 11:16:04 VERBOSE[5743] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Jul 20 11:16:04 VERBOSE[5743] logger.c: > Call Ref: len= 2 (reference 28/0x1C) (Originator)
Jul 20 11:16:04 VERBOSE[5743] logger.c: > Message type: RELEASE (77)
Jul 20 11:16:04 VERBOSE[5743] logger.c: > [08 02 81 91]
Jul 20 11:16:04 VERBOSE[5743] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
Jul 20 11:16:04 VERBOSE[5743] logger.c: > Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: Updated conferencing on 1, with 0 conference users
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:04 DEBUG[5743] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Hungup 'Zap/1-1'
Jul 20 11:16:04 VERBOSE[5743] logger.c: == Everyone is busy/congested at this time (1:1/0/0)
Jul 20 11:16:04 DEBUG[5743] app_dial.c: Exiting with DIALSTATUS=BUSY.
Jul 20 11:16:04 DEBUG[5743] app_macro.c: Executed application: Dial
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing Goto("SIP/325-b7905e28", "s-BUSY|1") in new stack
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Goto (macro-dialout-trunk,s-BUSY,1)
Jul 20 11:16:04 DEBUG[5743] app_macro.c: Executed application: Goto
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Dial failed due to trunk reporting BUSY - giving up") in new stack
Jul 20 11:16:04 DEBUG[5743] app_macro.c: Executed application: NoOp
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing Busy("SIP/325-b7905e28", "20") in new stack
Jul 20 11:16:04 VERBOSE[5743] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28' in macro 'dialout-trunk'
Jul 20 11:16:04 VERBOSE[5743] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing Macro("SIP/325-b7905e28", "hangupcall") in new stack
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing ResetCDR("SIP/325-b7905e28", "w") in new stack
Jul 20 11:16:04 DEBUG[5743] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 20 11:16:04 DEBUG[5743] 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) VALUES ('2007-07-20 11:16:02','243200325','243200325','96784806','from-internal', 'SIP/325-b7905e28','Zap/1-1','ResetCDR','w',2,0,'BUSY',3,'')
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '243200325'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '243200325'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '96784806'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is 'from-internal'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is 'SIP/325-b7905e28'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is 'Zap/1-1'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is 'ResetCDR'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is 'w'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '2007-07-20 11:16:02'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '(null)'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '2007-07-20 11:16:04'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '2'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '0'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is 'BUSY'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is 'DOCUMENTATION'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '(null)'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '1184894162.214'
Jul 20 11:16:04 DEBUG[5743] pbx.c: Function result is '(null)'
Jul 20 11:16:04 DEBUG[5743] app_macro.c: Executed application: ResetCDR
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing NoCDR("SIP/325-b7905e28", "") in new stack
Jul 20 11:16:04 NOTICE[5743] cdr.c: CDR on channel 'SIP/325-b7905e28' not posted
Jul 20 11:16:04 NOTICE[5743] cdr.c: CDR on channel 'SIP/325-b7905e28' lacks end
Jul 20 11:16:04 DEBUG[5743] app_macro.c: Executed application: NoCDR
Jul 20 11:16:04 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?skiprg") in new stack
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Goto (macro-hangupcall,s,6)
Jul 20 11:16:04 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:04 DEBUG[5743] pbx.c: Expression result is '1'
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?theend") in new stack
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Goto (macro-hangupcall,s,9)
Jul 20 11:16:04 DEBUG[5743] app_macro.c: Executed application: GotoIf
Jul 20 11:16:04 VERBOSE[5743] logger.c: -- Executing Wait("SIP/325-b7905e28", "5") in new stack
Jul 20 11:16:04 VERBOSE[5743] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28' in macro 'hangupcall'
Jul 20 11:16:04 VERBOSE[5743] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:04 DEBUG[5743] chan_sip.c: update_call_counter(325) - decrement call limit counter
Jul 20 11:16:04 DEBUG[3049] chan_sip.c: Stopping retransmission on 'f430a5fc4cda69e8@172.17.170.150' of Response 13022: Match Not Found
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- ACKing all packets from 7 to (but not including) 9
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- ACKing packet 8, new txqueue is -1 (-1 means empty)
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:04 VERBOSE[3127] logger.c: < N(S): 014 0: 0
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- ACKing all packets from 8 to (but not including) 9
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=5
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 28/0x1C) (Terminator)
Jul 20 11:16:04 VERBOSE[3127] logger.c: < Message type: RELEASE COMPLETE (90)
Jul 20 11:16:04 VERBOSE[3127] logger.c: Sending Receiver Ready (15)
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c:
Jul 20 11:16:04 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:04 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:04 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:07 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:07 DEBUG[3049] chan_sip.c: Stopping retransmission on '32f833beb32988f6@172.17.170.150' of Response 30900: Match Found
Jul 20 11:16:07 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:07 DEBUG[3049] chan_sip.c: Checking SIP call limits for device 325
Jul 20 11:16:07 DEBUG[3049] chan_sip.c: build_route: Contact hop: <sip:325@172.17.170.150:36408>
Jul 20 11:16:07 DEBUG[3010] channel.c: Avoiding initial deadlock for 'SIP/325-b7905e28'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Macro("SIP/325-b7905e28", "dialout-trunk|1|96784806||") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK=1") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "_NODEST=") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_NUMBER=96784806") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "ROUTE_PASSWD=") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=tr") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?noauth") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-dialout-trunk,s,8)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "GROUP()=OUT_1") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Macro("SIP/325-b7905e28", "user-callerid|SKIPTTL") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is 'device'
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '325'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "user-callerid: device 325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Noop
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Not taking any branch
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?start") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Not taking any branch
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '325'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: NoOp
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '325'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSER=325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is 'Ryan Williams'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSERCIDNAME=Ryan Williams") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Not taking any branch
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=Ryan Williams <325>") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '325'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "TTL: ARG1: SKIPTTL") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Noop
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?continue") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-user-callerid,s,21)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '"Ryan Williams" <325>'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Using CallerID "Ryan Williams" <325>") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: NoOp
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Macro
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '325'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Macro("SIP/325-b7905e28", "record-enable|325|OUT") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '0'
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?2:4") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-record-enable,s,4)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "recordingcheck|20070720-111607|1184894167.216") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 20 11:16:07 VERBOSE[5752] logger.c: recordingcheck|20070720-111607|1184894167.216: Outbound recording not enabled
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- AGI Script recordingcheck completed, returning 0
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "No recording needed") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Noop
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Macro
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?skipoutcid") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Not taking any branch
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Macro("SIP/325-b7905e28", "outbound-callerid|1") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?start") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-outbound-callerid,s,3)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: NoOp
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?normcid") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-outbound-callerid,s,9)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '243200325'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "USEROUTCID=243200325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] db.c: Unable to find key '325/emergency_cid' in family 'DEVICE'
Jul 20 11:16:07 DEBUG[5752] func_db.c: DB: DEVICE/325/emergency_cid not found in database.
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is ''
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "EMERGENCYCID=") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "TRUNKOUTCID=243200300") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?trunkcid") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-outbound-callerid,s,16)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?usercid") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Not taking any branch
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200300") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Not taking any branch
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200325") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is ''
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?report:hidecid") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-outbound-callerid,s,22)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is '"" <243200325>'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "CallerID set to "" <243200325>") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: NoOp
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Macro
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?nomax") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Goto (macro-dialout-trunk,s,16)
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "fixlocalprefix") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jul 20 11:16:07 VERBOSE[5752] logger.c: == fixlocalprefix: Dialpattern XXXXXXXX matched. 96784806 -> 96784806
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "OUTNUM=96784806") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Function result is 'ZAP/g0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Set("SIP/325-b7905e28", "custom=ZAP/g0") in new stack
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: Set
Jul 20 11:16:07 DEBUG[5752] pbx.c: Expression result is '0'
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?customtrunk") in new stack
Jul 20 11:16:07 DEBUG[5752] pbx.c: Not taking any branch
Jul 20 11:16:07 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Executing Dial("SIP/325-b7905e28", "ZAP/g0/96784806|300|") in new stack
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Requested transfer capability: 0x00 - SPEECH
Jul 20 11:16:07 VERBOSE[5752] logger.c:
Jul 20 11:16:07 VERBOSE[5752] logger.c:
Jul 20 11:16:07 VERBOSE[5752] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:07 VERBOSE[5752] logger.c: > N(S): 009 0: 0
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Restarting T203 counter
Jul 20 11:16:07 VERBOSE[5752] logger.c: Stopping T_203 timer
Jul 20 11:16:07 VERBOSE[5752] logger.c: Starting T_200 timer
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Protocol Discriminator: Q.931 (8) len=40
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Call Ref: len= 2 (reference 29/0x1D) (Originator)
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Message type: SETUP (5)
Jul 20 11:16:07 VERBOSE[5752] logger.c: > [04 03 80 90 a3]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Jul 20 11:16:07 VERBOSE[5752] logger.c: > [18 03 a9 83 81]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:07 VERBOSE[5752] logger.c: > ChanSel: Reserved
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Ext: 1 Channel: 1 ]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > [6c 0b 21 80 32 34 33 32 30 30 33 32 35]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Calling Number (len=13) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Presentation: Presentation permitted, user number not screened (0) '243200325' ]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > [70 09 c1 39 36 37 38 34 38 30 36]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Called Number (len=11) [ Ext: 1 TON: Subscriber Number (4) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '96784806' ]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > [a1]
Jul 20 11:16:07 VERBOSE[5752] logger.c: > Sending Complete (len= 1)
Jul 20 11:16:07 VERBOSE[5752] logger.c: -- Called g0/96784806
Jul 20 11:16:07 VERBOSE[3127] logger.c:
Jul 20 11:16:07 VERBOSE[3127] logger.c:
Jul 20 11:16:07 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:07 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:07 VERBOSE[3127] logger.c: -- ACKing all packets from 8 to (but not including) 10
Jul 20 11:16:07 VERBOSE[3127] logger.c: -- ACKing packet 9, new txqueue is -1 (-1 means empty)
Jul 20 11:16:07 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:07 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:07 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:08 VERBOSE[3127] logger.c:
Jul 20 11:16:08 VERBOSE[3127] logger.c:
Jul 20 11:16:08 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:08 VERBOSE[3127] logger.c: < N(S): 015 0: 0
Jul 20 11:16:08 VERBOSE[3127] logger.c: -- ACKing all packets from 9 to (but not including) 10
Jul 20 11:16:08 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:08 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:08 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:08 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Jul 20 11:16:08 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 29/0x1D) (Terminator)
Jul 20 11:16:08 VERBOSE[3127] logger.c: < Message type: CALL PROCEEDING (2)
Jul 20 11:16:08 VERBOSE[3127] logger.c: < [18 03 a9 83 81]
Jul 20 11:16:08 VERBOSE[3127] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:08 VERBOSE[3127] logger.c: < ChanSel: Reserved
Jul 20 11:16:08 VERBOSE[3127] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:08 VERBOSE[3127] logger.c: < Ext: 1 Channel: 1 ]
Jul 20 11:16:08 VERBOSE[3127] logger.c: Sending Receiver Ready (16)
Jul 20 11:16:08 VERBOSE[3127] logger.c:
Jul 20 11:16:08 VERBOSE[3127] logger.c:
Jul 20 11:16:08 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:08 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:08 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:08 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:08 DEBUG[3127] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
Jul 20 11:16:08 VERBOSE[5752] logger.c: -- Zap/1-1 is proceeding passing it to SIP/325-b7905e28
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:09 VERBOSE[3127] logger.c: < N(S): 016 0: 0
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- ACKing all packets from 9 to (but not including) 10
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 29/0x1D) (Terminator)
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Message type: DISCONNECT (69)
Jul 20 11:16:09 VERBOSE[3127] logger.c: < [08 02 80 91]
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0)
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:09 VERBOSE[3127] logger.c: < [1e 02 82 88]
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]
Jul 20 11:16:09 VERBOSE[3127] logger.c: Sending Receiver Ready (17)
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:09 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Channel 0/1, span 1 got hangup request
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Zap/1-1 is busy
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Jul 20 11:16:09 VERBOSE[5752] logger.c:
Jul 20 11:16:09 VERBOSE[5752] logger.c:
Jul 20 11:16:09 VERBOSE[5752] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:09 VERBOSE[5752] logger.c: > N(S): 010 0: 0
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Restarting T203 counter
Jul 20 11:16:09 VERBOSE[5752] logger.c: Stopping T_203 timer
Jul 20 11:16:09 VERBOSE[5752] logger.c: Starting T_200 timer
Jul 20 11:16:09 VERBOSE[5752] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Jul 20 11:16:09 VERBOSE[5752] logger.c: > Call Ref: len= 2 (reference 29/0x1D) (Originator)
Jul 20 11:16:09 VERBOSE[5752] logger.c: > Message type: RELEASE (77)
Jul 20 11:16:09 VERBOSE[5752] logger.c: > [08 02 81 91]
Jul 20 11:16:09 VERBOSE[5752] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
Jul 20 11:16:09 VERBOSE[5752] logger.c: > Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: Updated conferencing on 1, with 0 conference users
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:09 DEBUG[5752] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Hungup 'Zap/1-1'
Jul 20 11:16:09 VERBOSE[5752] logger.c: == Everyone is busy/congested at this time (1:1/0/0)
Jul 20 11:16:09 DEBUG[5752] app_dial.c: Exiting with DIALSTATUS=BUSY.
Jul 20 11:16:09 DEBUG[5752] app_macro.c: Executed application: Dial
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing Goto("SIP/325-b7905e28", "s-BUSY|1") in new stack
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Goto (macro-dialout-trunk,s-BUSY,1)
Jul 20 11:16:09 DEBUG[5752] app_macro.c: Executed application: Goto
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Dial failed due to trunk reporting BUSY - giving up") in new stack
Jul 20 11:16:09 DEBUG[5752] app_macro.c: Executed application: NoOp
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing Busy("SIP/325-b7905e28", "20") in new stack
Jul 20 11:16:09 VERBOSE[5752] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28' in macro 'dialout-trunk'
Jul 20 11:16:09 VERBOSE[5752] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing Macro("SIP/325-b7905e28", "hangupcall") in new stack
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing ResetCDR("SIP/325-b7905e28", "w") in new stack
Jul 20 11:16:09 DEBUG[5752] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 20 11:16:09 DEBUG[5752] 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) VALUES ('2007-07-20 11:16:07','243200325','243200325','96784806','from-internal', 'SIP/325-b7905e28','Zap/1-1','ResetCDR','w',2,0,'BUSY',3,'')
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '243200325'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '243200325'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '96784806'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is 'from-internal'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is 'SIP/325-b7905e28'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is 'Zap/1-1'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is 'ResetCDR'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is 'w'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '2007-07-20 11:16:07'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '(null)'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '2007-07-20 11:16:09'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '2'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '0'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is 'BUSY'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is 'DOCUMENTATION'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '(null)'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '1184894167.216'
Jul 20 11:16:09 DEBUG[5752] pbx.c: Function result is '(null)'
Jul 20 11:16:09 DEBUG[5752] app_macro.c: Executed application: ResetCDR
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing NoCDR("SIP/325-b7905e28", "") in new stack
Jul 20 11:16:09 NOTICE[5752] cdr.c: CDR on channel 'SIP/325-b7905e28' not posted
Jul 20 11:16:09 NOTICE[5752] cdr.c: CDR on channel 'SIP/325-b7905e28' lacks end
Jul 20 11:16:09 DEBUG[5752] app_macro.c: Executed application: NoCDR
Jul 20 11:16:09 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?skiprg") in new stack
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Goto (macro-hangupcall,s,6)
Jul 20 11:16:09 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:09 DEBUG[5752] pbx.c: Expression result is '1'
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?theend") in new stack
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Goto (macro-hangupcall,s,9)
Jul 20 11:16:09 DEBUG[5752] app_macro.c: Executed application: GotoIf
Jul 20 11:16:09 VERBOSE[5752] logger.c: -- Executing Wait("SIP/325-b7905e28", "5") in new stack
Jul 20 11:16:09 VERBOSE[5752] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28' in macro 'hangupcall'
Jul 20 11:16:09 VERBOSE[5752] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:09 DEBUG[5752] chan_sip.c: update_call_counter(325) - decrement call limit counter
Jul 20 11:16:09 DEBUG[3049] chan_sip.c: Stopping retransmission on '32f833beb32988f6@172.17.170.150' of Response 30901: Match Not Found
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- ACKing all packets from 9 to (but not including) 11
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- ACKing packet 10, new txqueue is -1 (-1 means empty)
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:09 VERBOSE[3127] logger.c: < N(S): 017 0: 0
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- ACKing all packets from 10 to (but not including) 11
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=5
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 29/0x1D) (Terminator)
Jul 20 11:16:09 VERBOSE[3127] logger.c: < Message type: RELEASE COMPLETE (90)
Jul 20 11:16:09 VERBOSE[3127] logger.c: Sending Receiver Ready (18)
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c:
Jul 20 11:16:09 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:09 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:09 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:11 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:11 DEBUG[3049] chan_sip.c: Stopping retransmission on 'd2533dcfc18c362f@172.17.170.150' of Response 12675: Match Found
Jul 20 11:16:11 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:11 DEBUG[3049] chan_sip.c: Checking SIP call limits for device 325
Jul 20 11:16:11 DEBUG[3049] chan_sip.c: build_route: Contact hop: <sip:325@172.17.170.150:36408>
Jul 20 11:16:11 DEBUG[3010] channel.c: Avoiding initial deadlock for 'SIP/325-b7905e28'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Macro("SIP/325-b7905e28", "dialout-trunk|1|96784806||") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK=1") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "_NODEST=") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_NUMBER=96784806") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "ROUTE_PASSWD=") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=tr") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?noauth") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-dialout-trunk,s,8)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "GROUP()=OUT_1") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Macro("SIP/325-b7905e28", "user-callerid|SKIPTTL") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is 'device'
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '325'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "user-callerid: device 325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Noop
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Not taking any branch
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?start") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Not taking any branch
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '325'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: NoOp
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '325'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSER=325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is 'Ryan Williams'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSERCIDNAME=Ryan Williams") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Not taking any branch
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=Ryan Williams <325>") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '325'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "TTL: ARG1: SKIPTTL") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Noop
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?continue") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-user-callerid,s,21)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '"Ryan Williams" <325>'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Using CallerID "Ryan Williams" <325>") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: NoOp
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Macro
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '325'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Macro("SIP/325-b7905e28", "record-enable|325|OUT") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '0'
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?2:4") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-record-enable,s,4)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "recordingcheck|20070720-111611|1184894171.218") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 20 11:16:11 VERBOSE[5761] logger.c: recordingcheck|20070720-111611|1184894171.218: Outbound recording not enabled
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- AGI Script recordingcheck completed, returning 0
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "No recording needed") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Noop
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Macro
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?skipoutcid") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Not taking any branch
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Macro("SIP/325-b7905e28", "outbound-callerid|1") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?start") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-outbound-callerid,s,3)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: NoOp
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?normcid") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-outbound-callerid,s,9)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '243200325'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "USEROUTCID=243200325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] db.c: Unable to find key '325/emergency_cid' in family 'DEVICE'
Jul 20 11:16:11 DEBUG[5761] func_db.c: DB: DEVICE/325/emergency_cid not found in database.
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is ''
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "EMERGENCYCID=") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "TRUNKOUTCID=243200300") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?trunkcid") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-outbound-callerid,s,16)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?usercid") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Not taking any branch
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200300") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Not taking any branch
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200325") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is ''
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?report:hidecid") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-outbound-callerid,s,22)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is '"" <243200325>'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "CallerID set to "" <243200325>") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: NoOp
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Macro
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?nomax") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Goto (macro-dialout-trunk,s,16)
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "fixlocalprefix") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jul 20 11:16:11 VERBOSE[5761] logger.c: == fixlocalprefix: Dialpattern XXXXXXXX matched. 96784806 -> 96784806
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "OUTNUM=96784806") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Function result is 'ZAP/g0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Set("SIP/325-b7905e28", "custom=ZAP/g0") in new stack
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: Set
Jul 20 11:16:11 DEBUG[5761] pbx.c: Expression result is '0'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?customtrunk") in new stack
Jul 20 11:16:11 DEBUG[5761] pbx.c: Not taking any branch
Jul 20 11:16:11 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Executing Dial("SIP/325-b7905e28", "ZAP/g0/96784806|300|") in new stack
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Requested transfer capability: 0x00 - SPEECH
Jul 20 11:16:11 VERBOSE[5761] logger.c:
Jul 20 11:16:11 VERBOSE[5761] logger.c:
Jul 20 11:16:11 VERBOSE[5761] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:11 VERBOSE[5761] logger.c: > N(S): 011 0: 0
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Restarting T203 counter
Jul 20 11:16:11 VERBOSE[5761] logger.c: Stopping T_203 timer
Jul 20 11:16:11 VERBOSE[5761] logger.c: Starting T_200 timer
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Protocol Discriminator: Q.931 (8) len=40
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Call Ref: len= 2 (reference 30/0x1E) (Originator)
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Message type: SETUP (5)
Jul 20 11:16:11 VERBOSE[5761] logger.c: > [04 03 80 90 a3]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Jul 20 11:16:11 VERBOSE[5761] logger.c: > [18 03 a9 83 81]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:11 VERBOSE[5761] logger.c: > ChanSel: Reserved
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Ext: 1 Channel: 1 ]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > [6c 0b 21 80 32 34 33 32 30 30 33 32 35]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Calling Number (len=13) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Presentation: Presentation permitted, user number not screened (0) '243200325' ]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > [70 09 c1 39 36 37 38 34 38 30 36]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Called Number (len=11) [ Ext: 1 TON: Subscriber Number (4) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '96784806' ]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > [a1]
Jul 20 11:16:11 VERBOSE[5761] logger.c: > Sending Complete (len= 1)
Jul 20 11:16:11 DEBUG[3010] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Called g0/96784806
Jul 20 11:16:11 VERBOSE[3127] logger.c:
Jul 20 11:16:11 VERBOSE[3127] logger.c:
Jul 20 11:16:11 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:11 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- ACKing all packets from 10 to (but not including) 12
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- ACKing packet 11, new txqueue is -1 (-1 means empty)
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:11 VERBOSE[3127] logger.c:
Jul 20 11:16:11 VERBOSE[3127] logger.c:
Jul 20 11:16:11 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:11 VERBOSE[3127] logger.c: < N(S): 018 0: 0
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- ACKing all packets from 11 to (but not including) 12
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:11 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Jul 20 11:16:11 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 30/0x1E) (Terminator)
Jul 20 11:16:11 VERBOSE[3127] logger.c: < Message type: CALL PROCEEDING (2)
Jul 20 11:16:11 VERBOSE[3127] logger.c: < [18 03 a9 83 81]
Jul 20 11:16:11 VERBOSE[3127] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:11 VERBOSE[3127] logger.c: < ChanSel: Reserved
Jul 20 11:16:11 VERBOSE[3127] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:11 VERBOSE[3127] logger.c: < Ext: 1 Channel: 1 ]
Jul 20 11:16:11 VERBOSE[3127] logger.c: Sending Receiver Ready (19)
Jul 20 11:16:11 VERBOSE[3127] logger.c:
Jul 20 11:16:11 VERBOSE[3127] logger.c:
Jul 20 11:16:11 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:11 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:11 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:11 DEBUG[3127] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
Jul 20 11:16:11 VERBOSE[5761] logger.c: -- Zap/1-1 is proceeding passing it to SIP/325-b7905e28
Jul 20 11:16:12 VERBOSE[3127] logger.c:
Jul 20 11:16:12 VERBOSE[3127] logger.c:
Jul 20 11:16:12 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:12 VERBOSE[3127] logger.c: < N(S): 019 0: 0
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- ACKing all packets from 11 to (but not including) 12
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 30/0x1E) (Terminator)
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Message type: DISCONNECT (69)
Jul 20 11:16:12 VERBOSE[3127] logger.c: < [08 02 80 91]
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0)
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:12 VERBOSE[3127] logger.c: < [1e 02 82 88]
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]
Jul 20 11:16:12 VERBOSE[3127] logger.c: Sending Receiver Ready (20)
Jul 20 11:16:12 VERBOSE[3127] logger.c:
Jul 20 11:16:12 VERBOSE[3127] logger.c:
Jul 20 11:16:12 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:12 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Channel 0/1, span 1 got hangup request
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Zap/1-1 is busy
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Jul 20 11:16:12 VERBOSE[5761] logger.c:
Jul 20 11:16:12 VERBOSE[5761] logger.c:
Jul 20 11:16:12 VERBOSE[5761] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:12 VERBOSE[5761] logger.c: > N(S): 012 0: 0
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Restarting T203 counter
Jul 20 11:16:12 VERBOSE[5761] logger.c: Stopping T_203 timer
Jul 20 11:16:12 VERBOSE[5761] logger.c: Starting T_200 timer
Jul 20 11:16:12 VERBOSE[5761] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Jul 20 11:16:12 VERBOSE[5761] logger.c: > Call Ref: len= 2 (reference 30/0x1E) (Originator)
Jul 20 11:16:12 VERBOSE[5761] logger.c: > Message type: RELEASE (77)
Jul 20 11:16:12 VERBOSE[5761] logger.c: > [08 02 81 91]
Jul 20 11:16:12 VERBOSE[5761] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
Jul 20 11:16:12 VERBOSE[5761] logger.c: > Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: Updated conferencing on 1, with 0 conference users
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:12 DEBUG[5761] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Hungup 'Zap/1-1'
Jul 20 11:16:12 VERBOSE[5761] logger.c: == Everyone is busy/congested at this time (1:1/0/0)
Jul 20 11:16:12 DEBUG[5761] app_dial.c: Exiting with DIALSTATUS=BUSY.
Jul 20 11:16:12 DEBUG[5761] app_macro.c: Executed application: Dial
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing Goto("SIP/325-b7905e28", "s-BUSY|1") in new stack
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Goto (macro-dialout-trunk,s-BUSY,1)
Jul 20 11:16:12 DEBUG[5761] app_macro.c: Executed application: Goto
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Dial failed due to trunk reporting BUSY - giving up") in new stack
Jul 20 11:16:12 DEBUG[5761] app_macro.c: Executed application: NoOp
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing Busy("SIP/325-b7905e28", "20") in new stack
Jul 20 11:16:12 VERBOSE[5761] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28' in macro 'dialout-trunk'
Jul 20 11:16:12 VERBOSE[5761] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing Macro("SIP/325-b7905e28", "hangupcall") in new stack
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing ResetCDR("SIP/325-b7905e28", "w") in new stack
Jul 20 11:16:12 DEBUG[5761] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 20 11:16:12 DEBUG[5761] 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) VALUES ('2007-07-20 11:16:11','243200325','243200325','96784806','from-internal', 'SIP/325-b7905e28','Zap/1-1','ResetCDR','w',1,0,'BUSY',3,'')
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '243200325'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '243200325'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '96784806'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is 'from-internal'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is 'SIP/325-b7905e28'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is 'Zap/1-1'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is 'ResetCDR'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is 'w'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '2007-07-20 11:16:11'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '(null)'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '2007-07-20 11:16:12'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '1'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '0'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is 'BUSY'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is 'DOCUMENTATION'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '(null)'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '1184894171.218'
Jul 20 11:16:12 DEBUG[5761] pbx.c: Function result is '(null)'
Jul 20 11:16:12 DEBUG[5761] app_macro.c: Executed application: ResetCDR
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing NoCDR("SIP/325-b7905e28", "") in new stack
Jul 20 11:16:12 NOTICE[5761] cdr.c: CDR on channel 'SIP/325-b7905e28' not posted
Jul 20 11:16:12 NOTICE[5761] cdr.c: CDR on channel 'SIP/325-b7905e28' lacks end
Jul 20 11:16:12 DEBUG[5761] app_macro.c: Executed application: NoCDR
Jul 20 11:16:12 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?skiprg") in new stack
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Goto (macro-hangupcall,s,6)
Jul 20 11:16:12 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:12 DEBUG[5761] pbx.c: Expression result is '1'
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?theend") in new stack
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Goto (macro-hangupcall,s,9)
Jul 20 11:16:12 DEBUG[5761] app_macro.c: Executed application: GotoIf
Jul 20 11:16:12 VERBOSE[5761] logger.c: -- Executing Wait("SIP/325-b7905e28", "5") in new stack
Jul 20 11:16:12 VERBOSE[5761] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28' in macro 'hangupcall'
Jul 20 11:16:12 VERBOSE[5761] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:12 DEBUG[5761] chan_sip.c: update_call_counter(325) - decrement call limit counter
Jul 20 11:16:12 DEBUG[3049] chan_sip.c: Stopping retransmission on 'd2533dcfc18c362f@172.17.170.150' of Response 12676: Match Not Found
Jul 20 11:16:12 VERBOSE[3127] logger.c:
Jul 20 11:16:12 VERBOSE[3127] logger.c:
Jul 20 11:16:12 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:12 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- ACKing all packets from 11 to (but not including) 13
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- ACKing packet 12, new txqueue is -1 (-1 means empty)
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:12 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:13 VERBOSE[3127] logger.c:
Jul 20 11:16:13 VERBOSE[3127] logger.c:
Jul 20 11:16:13 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:13 VERBOSE[3127] logger.c: < N(S): 020 0: 0
Jul 20 11:16:13 VERBOSE[3127] logger.c: -- ACKing all packets from 12 to (but not including) 13
Jul 20 11:16:13 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:13 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:13 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:13 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=5
Jul 20 11:16:13 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 30/0x1E) (Terminator)
Jul 20 11:16:13 VERBOSE[3127] logger.c: < Message type: RELEASE COMPLETE (90)
Jul 20 11:16:13 VERBOSE[3127] logger.c: Sending Receiver Ready (21)
Jul 20 11:16:13 VERBOSE[3127] logger.c:
Jul 20 11:16:13 VERBOSE[3127] logger.c:
Jul 20 11:16:13 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:13 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:13 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:13 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:15 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:15 DEBUG[3049] chan_sip.c: Stopping retransmission on '32f8b2be00c82feb@172.17.170.150' of Response 61150: Match Found
Jul 20 11:16:15 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:15 DEBUG[3049] chan_sip.c: Checking SIP call limits for device 325
Jul 20 11:16:15 DEBUG[3049] chan_sip.c: build_route: Contact hop: <sip:325@172.17.170.150:36408>
Jul 20 11:16:15 DEBUG[3010] channel.c: Avoiding initial deadlock for 'SIP/325-b7905e28'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Macro("SIP/325-b7905e28", "dialout-trunk|1|96784806||") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK=1") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "_NODEST=") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_NUMBER=96784806") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "ROUTE_PASSWD=") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=tr") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?noauth") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-dialout-trunk,s,8)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "GROUP()=OUT_1") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Macro("SIP/325-b7905e28", "user-callerid|SKIPTTL") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is 'device'
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '325'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "user-callerid: device 325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Noop
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Not taking any branch
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?start") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Not taking any branch
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '325'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: NoOp
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '325'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSER=325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is 'Ryan Williams'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSERCIDNAME=Ryan Williams") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Not taking any branch
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=Ryan Williams <325>") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '325'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "TTL: ARG1: SKIPTTL") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Noop
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?continue") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-user-callerid,s,21)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '"Ryan Williams" <325>'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Using CallerID "Ryan Williams" <325>") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: NoOp
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Macro
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '325'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Macro("SIP/325-b7905e28", "record-enable|325|OUT") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '0'
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?2:4") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-record-enable,s,4)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "recordingcheck|20070720-111615|1184894175.220") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 20 11:16:15 VERBOSE[5770] logger.c: recordingcheck|20070720-111615|1184894175.220: Outbound recording not enabled
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- AGI Script recordingcheck completed, returning 0
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "No recording needed") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Noop
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Macro
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?skipoutcid") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Not taking any branch
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Macro("SIP/325-b7905e28", "outbound-callerid|1") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?start") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-outbound-callerid,s,3)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: NoOp
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?normcid") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-outbound-callerid,s,9)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '243200325'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "USEROUTCID=243200325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] db.c: Unable to find key '325/emergency_cid' in family 'DEVICE'
Jul 20 11:16:15 DEBUG[5770] func_db.c: DB: DEVICE/325/emergency_cid not found in database.
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is ''
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "EMERGENCYCID=") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "TRUNKOUTCID=243200300") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?trunkcid") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-outbound-callerid,s,16)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?usercid") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Not taking any branch
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200300") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Not taking any branch
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200325") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is ''
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?report:hidecid") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-outbound-callerid,s,22)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is '"" <243200325>'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "CallerID set to "" <243200325>") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: NoOp
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Macro
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?nomax") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Goto (macro-dialout-trunk,s,16)
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "fixlocalprefix") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jul 20 11:16:15 VERBOSE[5770] logger.c: == fixlocalprefix: Dialpattern XXXXXXXX matched. 96784806 -> 96784806
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "OUTNUM=96784806") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Function result is 'ZAP/g0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Set("SIP/325-b7905e28", "custom=ZAP/g0") in new stack
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: Set
Jul 20 11:16:15 DEBUG[5770] pbx.c: Expression result is '0'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?customtrunk") in new stack
Jul 20 11:16:15 DEBUG[5770] pbx.c: Not taking any branch
Jul 20 11:16:15 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Executing Dial("SIP/325-b7905e28", "ZAP/g0/96784806|300|") in new stack
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Requested transfer capability: 0x00 - SPEECH
Jul 20 11:16:15 VERBOSE[5770] logger.c:
Jul 20 11:16:15 VERBOSE[5770] logger.c:
Jul 20 11:16:15 VERBOSE[5770] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:15 VERBOSE[5770] logger.c: > N(S): 013 0: 0
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Restarting T203 counter
Jul 20 11:16:15 VERBOSE[5770] logger.c: Stopping T_203 timer
Jul 20 11:16:15 VERBOSE[5770] logger.c: Starting T_200 timer
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Protocol Discriminator: Q.931 (8) len=40
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Call Ref: len= 2 (reference 31/0x1F) (Originator)
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Message type: SETUP (5)
Jul 20 11:16:15 VERBOSE[5770] logger.c: > [04 03 80 90 a3]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Jul 20 11:16:15 VERBOSE[5770] logger.c: > [18 03 a9 83 81]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:15 VERBOSE[5770] logger.c: > ChanSel: Reserved
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Ext: 1 Channel: 1 ]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > [6c 0b 21 80 32 34 33 32 30 30 33 32 35]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Calling Number (len=13) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Presentation: Presentation permitted, user number not screened (0) '243200325' ]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > [70 09 c1 39 36 37 38 34 38 30 36]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Called Number (len=11) [ Ext: 1 TON: Subscriber Number (4) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '96784806' ]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > [a1]
Jul 20 11:16:15 VERBOSE[5770] logger.c: > Sending Complete (len= 1)
Jul 20 11:16:15 DEBUG[3010] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Called g0/96784806
Jul 20 11:16:15 VERBOSE[3127] logger.c:
Jul 20 11:16:15 VERBOSE[3127] logger.c:
Jul 20 11:16:15 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:15 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- ACKing all packets from 12 to (but not including) 14
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- ACKing packet 13, new txqueue is -1 (-1 means empty)
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:15 VERBOSE[3127] logger.c:
Jul 20 11:16:15 VERBOSE[3127] logger.c:
Jul 20 11:16:15 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:15 VERBOSE[3127] logger.c: < N(S): 021 0: 0
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- ACKing all packets from 13 to (but not including) 14
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:15 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Jul 20 11:16:15 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 31/0x1F) (Terminator)
Jul 20 11:16:15 VERBOSE[3127] logger.c: < Message type: CALL PROCEEDING (2)
Jul 20 11:16:15 VERBOSE[3127] logger.c: < [18 03 a9 83 81]
Jul 20 11:16:15 VERBOSE[3127] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:15 VERBOSE[3127] logger.c: < ChanSel: Reserved
Jul 20 11:16:15 VERBOSE[3127] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:15 VERBOSE[3127] logger.c: < Ext: 1 Channel: 1 ]
Jul 20 11:16:15 VERBOSE[3127] logger.c: Sending Receiver Ready (22)
Jul 20 11:16:15 VERBOSE[3127] logger.c:
Jul 20 11:16:15 VERBOSE[3127] logger.c:
Jul 20 11:16:15 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:15 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:15 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:15 DEBUG[3127] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
Jul 20 11:16:15 VERBOSE[5770] logger.c: -- Zap/1-1 is proceeding passing it to SIP/325-b7905e28
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:16 VERBOSE[3127] logger.c: < N(S): 022 0: 0
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- ACKing all packets from 13 to (but not including) 14
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 31/0x1F) (Terminator)
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Message type: DISCONNECT (69)
Jul 20 11:16:16 VERBOSE[3127] logger.c: < [08 02 80 91]
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0)
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:16 VERBOSE[3127] logger.c: < [1e 02 82 88]
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]
Jul 20 11:16:16 VERBOSE[3127] logger.c: Sending Receiver Ready (23)
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:16 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Channel 0/1, span 1 got hangup request
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Zap/1-1 is busy
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Jul 20 11:16:16 VERBOSE[5770] logger.c:
Jul 20 11:16:16 VERBOSE[5770] logger.c:
Jul 20 11:16:16 VERBOSE[5770] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:16 VERBOSE[5770] logger.c: > N(S): 014 0: 0
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Restarting T203 counter
Jul 20 11:16:16 VERBOSE[5770] logger.c: Stopping T_203 timer
Jul 20 11:16:16 VERBOSE[5770] logger.c: Starting T_200 timer
Jul 20 11:16:16 VERBOSE[5770] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Jul 20 11:16:16 VERBOSE[5770] logger.c: > Call Ref: len= 2 (reference 31/0x1F) (Originator)
Jul 20 11:16:16 VERBOSE[5770] logger.c: > Message type: RELEASE (77)
Jul 20 11:16:16 VERBOSE[5770] logger.c: > [08 02 81 91]
Jul 20 11:16:16 VERBOSE[5770] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
Jul 20 11:16:16 VERBOSE[5770] logger.c: > Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: Updated conferencing on 1, with 0 conference users
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:16 DEBUG[5770] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Hungup 'Zap/1-1'
Jul 20 11:16:16 VERBOSE[5770] logger.c: == Everyone is busy/congested at this time (1:1/0/0)
Jul 20 11:16:16 DEBUG[5770] app_dial.c: Exiting with DIALSTATUS=BUSY.
Jul 20 11:16:16 DEBUG[5770] app_macro.c: Executed application: Dial
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing Goto("SIP/325-b7905e28", "s-BUSY|1") in new stack
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Goto (macro-dialout-trunk,s-BUSY,1)
Jul 20 11:16:16 DEBUG[5770] app_macro.c: Executed application: Goto
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Dial failed due to trunk reporting BUSY - giving up") in new stack
Jul 20 11:16:16 DEBUG[5770] app_macro.c: Executed application: NoOp
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing Busy("SIP/325-b7905e28", "20") in new stack
Jul 20 11:16:16 VERBOSE[5770] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28' in macro 'dialout-trunk'
Jul 20 11:16:16 VERBOSE[5770] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing Macro("SIP/325-b7905e28", "hangupcall") in new stack
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing ResetCDR("SIP/325-b7905e28", "w") in new stack
Jul 20 11:16:16 DEBUG[5770] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 20 11:16:16 DEBUG[5770] 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) VALUES ('2007-07-20 11:16:15','243200325','243200325','96784806','from-internal', 'SIP/325-b7905e28','Zap/1-1','ResetCDR','w',1,0,'BUSY',3,'')
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '243200325'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '243200325'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '96784806'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is 'from-internal'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is 'SIP/325-b7905e28'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is 'Zap/1-1'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is 'ResetCDR'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is 'w'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '2007-07-20 11:16:15'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '(null)'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '2007-07-20 11:16:16'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '1'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '0'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is 'BUSY'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is 'DOCUMENTATION'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '(null)'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '1184894175.220'
Jul 20 11:16:16 DEBUG[5770] pbx.c: Function result is '(null)'
Jul 20 11:16:16 DEBUG[5770] app_macro.c: Executed application: ResetCDR
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing NoCDR("SIP/325-b7905e28", "") in new stack
Jul 20 11:16:16 NOTICE[5770] cdr.c: CDR on channel 'SIP/325-b7905e28' not posted
Jul 20 11:16:16 NOTICE[5770] cdr.c: CDR on channel 'SIP/325-b7905e28' lacks end
Jul 20 11:16:16 DEBUG[5770] app_macro.c: Executed application: NoCDR
Jul 20 11:16:16 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?skiprg") in new stack
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Goto (macro-hangupcall,s,6)
Jul 20 11:16:16 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:16 DEBUG[5770] pbx.c: Expression result is '1'
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?theend") in new stack
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Goto (macro-hangupcall,s,9)
Jul 20 11:16:16 DEBUG[5770] app_macro.c: Executed application: GotoIf
Jul 20 11:16:16 VERBOSE[5770] logger.c: -- Executing Wait("SIP/325-b7905e28", "5") in new stack
Jul 20 11:16:16 VERBOSE[5770] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28' in macro 'hangupcall'
Jul 20 11:16:16 VERBOSE[5770] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:16 DEBUG[5770] chan_sip.c: update_call_counter(325) - decrement call limit counter
Jul 20 11:16:16 DEBUG[3049] chan_sip.c: Stopping retransmission on '32f8b2be00c82feb@172.17.170.150' of Response 61151: Match Not Found
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- ACKing all packets from 13 to (but not including) 15
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- ACKing packet 14, new txqueue is -1 (-1 means empty)
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:16 VERBOSE[3127] logger.c: < N(S): 023 0: 0
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- ACKing all packets from 14 to (but not including) 15
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=5
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 31/0x1F) (Terminator)
Jul 20 11:16:16 VERBOSE[3127] logger.c: < Message type: RELEASE COMPLETE (90)
Jul 20 11:16:16 VERBOSE[3127] logger.c: Sending Receiver Ready (24)
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c:
Jul 20 11:16:16 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:16 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:16 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:18 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:18 DEBUG[3049] chan_sip.c: Stopping retransmission on '0dccab9df10b7399@172.17.170.150' of Response 12557: Match Found
Jul 20 11:16:18 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:18 DEBUG[3049] chan_sip.c: Checking SIP call limits for device 325
Jul 20 11:16:18 DEBUG[3049] chan_sip.c: build_route: Contact hop: <sip:325@172.17.170.150:36408>
Jul 20 11:16:18 DEBUG[3010] channel.c: Avoiding initial deadlock for 'SIP/325-b7905e28'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Macro("SIP/325-b7905e28", "dialout-trunk|1|96784806||") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK=1") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "_NODEST=") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_NUMBER=96784806") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "ROUTE_PASSWD=") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=tr") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?noauth") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-dialout-trunk,s,8)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "GROUP()=OUT_1") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Macro("SIP/325-b7905e28", "user-callerid|SKIPTTL") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is 'device'
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '325'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "user-callerid: device 325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Noop
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Not taking any branch
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?start") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Not taking any branch
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '325'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: NoOp
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '325'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSER=325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is 'Ryan Williams'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSERCIDNAME=Ryan Williams") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Not taking any branch
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=Ryan Williams <325>") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '325'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "TTL: ARG1: SKIPTTL") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Noop
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?continue") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-user-callerid,s,21)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '"Ryan Williams" <325>'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Using CallerID "Ryan Williams" <325>") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: NoOp
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Macro
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '325'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Macro("SIP/325-b7905e28", "record-enable|325|OUT") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '0'
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?2:4") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-record-enable,s,4)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "recordingcheck|20070720-111618|1184894178.222") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 20 11:16:18 VERBOSE[5779] logger.c: recordingcheck|20070720-111618|1184894178.222: Outbound recording not enabled
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- AGI Script recordingcheck completed, returning 0
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "No recording needed") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Noop
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Macro
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?skipoutcid") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Not taking any branch
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Macro("SIP/325-b7905e28", "outbound-callerid|1") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?start") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-outbound-callerid,s,3)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: NoOp
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?normcid") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-outbound-callerid,s,9)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '243200325'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "USEROUTCID=243200325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] db.c: Unable to find key '325/emergency_cid' in family 'DEVICE'
Jul 20 11:16:18 DEBUG[5779] func_db.c: DB: DEVICE/325/emergency_cid not found in database.
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is ''
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "EMERGENCYCID=") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "TRUNKOUTCID=243200300") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?trunkcid") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-outbound-callerid,s,16)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?usercid") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Not taking any branch
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200300") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Not taking any branch
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200325") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is ''
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?report:hidecid") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-outbound-callerid,s,22)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is '"" <243200325>'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "CallerID set to "" <243200325>") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: NoOp
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Macro
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?nomax") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Goto (macro-dialout-trunk,s,16)
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "fixlocalprefix") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jul 20 11:16:18 VERBOSE[5779] logger.c: == fixlocalprefix: Dialpattern XXXXXXXX matched. 96784806 -> 96784806
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "OUTNUM=96784806") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Function result is 'ZAP/g0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Set("SIP/325-b7905e28", "custom=ZAP/g0") in new stack
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: Set
Jul 20 11:16:18 DEBUG[5779] pbx.c: Expression result is '0'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?customtrunk") in new stack
Jul 20 11:16:18 DEBUG[5779] pbx.c: Not taking any branch
Jul 20 11:16:18 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Executing Dial("SIP/325-b7905e28", "ZAP/g0/96784806|300|") in new stack
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Requested transfer capability: 0x00 - SPEECH
Jul 20 11:16:18 VERBOSE[5779] logger.c:
Jul 20 11:16:18 VERBOSE[5779] logger.c:
Jul 20 11:16:18 VERBOSE[5779] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:18 VERBOSE[5779] logger.c: > N(S): 015 0: 0
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Restarting T203 counter
Jul 20 11:16:18 VERBOSE[5779] logger.c: Stopping T_203 timer
Jul 20 11:16:18 VERBOSE[5779] logger.c: Starting T_200 timer
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Protocol Discriminator: Q.931 (8) len=40
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Call Ref: len= 2 (reference 32/0x20) (Originator)
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Message type: SETUP (5)
Jul 20 11:16:18 VERBOSE[5779] logger.c: > [04 03 80 90 a3]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Jul 20 11:16:18 VERBOSE[5779] logger.c: > [18 03 a9 83 81]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:18 VERBOSE[5779] logger.c: > ChanSel: Reserved
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Ext: 1 Channel: 1 ]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > [6c 0b 21 80 32 34 33 32 30 30 33 32 35]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Calling Number (len=13) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Presentation: Presentation permitted, user number not screened (0) '243200325' ]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > [70 09 c1 39 36 37 38 34 38 30 36]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Called Number (len=11) [ Ext: 1 TON: Subscriber Number (4) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '96784806' ]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > [a1]
Jul 20 11:16:18 VERBOSE[5779] logger.c: > Sending Complete (len= 1)
Jul 20 11:16:18 DEBUG[3010] channel.c: Avoiding initial deadlock for 'Zap/1-1'
Jul 20 11:16:18 VERBOSE[5779] logger.c: -- Called g0/96784806
Jul 20 11:16:18 VERBOSE[3127] logger.c:
Jul 20 11:16:18 VERBOSE[3127] logger.c:
Jul 20 11:16:18 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:18 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:18 VERBOSE[3127] logger.c: -- ACKing all packets from 14 to (but not including) 16
Jul 20 11:16:18 VERBOSE[3127] logger.c: -- ACKing packet 15, new txqueue is -1 (-1 means empty)
Jul 20 11:16:18 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:18 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:18 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:19 VERBOSE[3127] logger.c:
Jul 20 11:16:19 VERBOSE[3127] logger.c:
Jul 20 11:16:19 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:19 VERBOSE[3127] logger.c: < N(S): 024 0: 0
Jul 20 11:16:19 VERBOSE[3127] logger.c: -- ACKing all packets from 15 to (but not including) 16
Jul 20 11:16:19 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:19 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:19 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:19 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Jul 20 11:16:19 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 32/0x20) (Terminator)
Jul 20 11:16:19 VERBOSE[3127] logger.c: < Message type: CALL PROCEEDING (2)
Jul 20 11:16:19 VERBOSE[3127] logger.c: < [18 03 a9 83 81]
Jul 20 11:16:19 VERBOSE[3127] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:19 VERBOSE[3127] logger.c: < ChanSel: Reserved
Jul 20 11:16:19 VERBOSE[3127] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:19 VERBOSE[3127] logger.c: < Ext: 1 Channel: 1 ]
Jul 20 11:16:19 VERBOSE[3127] logger.c: Sending Receiver Ready (25)
Jul 20 11:16:19 VERBOSE[3127] logger.c:
Jul 20 11:16:19 VERBOSE[3127] logger.c:
Jul 20 11:16:19 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:19 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:19 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:19 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:19 DEBUG[3127] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
Jul 20 11:16:19 VERBOSE[5779] logger.c: -- Zap/1-1 is proceeding passing it to SIP/325-b7905e28
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:20 VERBOSE[3127] logger.c: < N(S): 025 0: 0
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- ACKing all packets from 15 to (but not including) 16
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 32/0x20) (Terminator)
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Message type: DISCONNECT (69)
Jul 20 11:16:20 VERBOSE[3127] logger.c: < [08 02 80 91]
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0)
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:20 VERBOSE[3127] logger.c: < [1e 02 82 88]
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2)
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]
Jul 20 11:16:20 VERBOSE[3127] logger.c: Sending Receiver Ready (26)
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:20 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Channel 0/1, span 1 got hangup request
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Zap/1-1 is busy
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Jul 20 11:16:20 VERBOSE[5779] logger.c:
Jul 20 11:16:20 VERBOSE[5779] logger.c:
Jul 20 11:16:20 VERBOSE[5779] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:20 VERBOSE[5779] logger.c: > N(S): 016 0: 0
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Restarting T203 counter
Jul 20 11:16:20 VERBOSE[5779] logger.c: Stopping T_203 timer
Jul 20 11:16:20 VERBOSE[5779] logger.c: Starting T_200 timer
Jul 20 11:16:20 VERBOSE[5779] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Jul 20 11:16:20 VERBOSE[5779] logger.c: > Call Ref: len= 2 (reference 32/0x20) (Originator)
Jul 20 11:16:20 VERBOSE[5779] logger.c: > Message type: RELEASE (77)
Jul 20 11:16:20 VERBOSE[5779] logger.c: > [08 02 81 91]
Jul 20 11:16:20 VERBOSE[5779] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
Jul 20 11:16:20 VERBOSE[5779] logger.c: > Ext: 1 Cause: User busy (17), class = Normal Event (1) ]
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: Updated conferencing on 1, with 0 conference users
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:20 DEBUG[5779] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Hungup 'Zap/1-1'
Jul 20 11:16:20 VERBOSE[5779] logger.c: == Everyone is busy/congested at this time (1:1/0/0)
Jul 20 11:16:20 DEBUG[5779] app_dial.c: Exiting with DIALSTATUS=BUSY.
Jul 20 11:16:20 DEBUG[5779] app_macro.c: Executed application: Dial
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing Goto("SIP/325-b7905e28", "s-BUSY|1") in new stack
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Goto (macro-dialout-trunk,s-BUSY,1)
Jul 20 11:16:20 DEBUG[5779] app_macro.c: Executed application: Goto
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Dial failed due to trunk reporting BUSY - giving up") in new stack
Jul 20 11:16:20 DEBUG[5779] app_macro.c: Executed application: NoOp
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing Busy("SIP/325-b7905e28", "20") in new stack
Jul 20 11:16:20 VERBOSE[5779] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28' in macro 'dialout-trunk'
Jul 20 11:16:20 VERBOSE[5779] logger.c: == Spawn extension (macro-dialout-trunk, s-BUSY, 2) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing Macro("SIP/325-b7905e28", "hangupcall") in new stack
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing ResetCDR("SIP/325-b7905e28", "w") in new stack
Jul 20 11:16:20 DEBUG[5779] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 20 11:16:20 DEBUG[5779] 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) VALUES ('2007-07-20 11:16:18','243200325','243200325','96784806','from-internal', 'SIP/325-b7905e28','Zap/1-1','ResetCDR','w',2,0,'BUSY',3,'')
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '243200325'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '243200325'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '96784806'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is 'from-internal'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is 'SIP/325-b7905e28'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is 'Zap/1-1'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is 'ResetCDR'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is 'w'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '2007-07-20 11:16:18'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '(null)'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '2007-07-20 11:16:20'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '2'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '0'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is 'BUSY'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is 'DOCUMENTATION'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '(null)'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '1184894178.222'
Jul 20 11:16:20 DEBUG[5779] pbx.c: Function result is '(null)'
Jul 20 11:16:20 DEBUG[5779] app_macro.c: Executed application: ResetCDR
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing NoCDR("SIP/325-b7905e28", "") in new stack
Jul 20 11:16:20 NOTICE[5779] cdr.c: CDR on channel 'SIP/325-b7905e28' not posted
Jul 20 11:16:20 NOTICE[5779] cdr.c: CDR on channel 'SIP/325-b7905e28' lacks end
Jul 20 11:16:20 DEBUG[5779] app_macro.c: Executed application: NoCDR
Jul 20 11:16:20 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?skiprg") in new stack
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Goto (macro-hangupcall,s,6)
Jul 20 11:16:20 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:20 DEBUG[5779] pbx.c: Expression result is '1'
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?theend") in new stack
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Goto (macro-hangupcall,s,9)
Jul 20 11:16:20 DEBUG[5779] app_macro.c: Executed application: GotoIf
Jul 20 11:16:20 VERBOSE[5779] logger.c: -- Executing Wait("SIP/325-b7905e28", "5") in new stack
Jul 20 11:16:20 VERBOSE[5779] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28' in macro 'hangupcall'
Jul 20 11:16:20 VERBOSE[5779] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:20 DEBUG[5779] chan_sip.c: update_call_counter(325) - decrement call limit counter
Jul 20 11:16:20 DEBUG[3049] chan_sip.c: Stopping retransmission on '0dccab9df10b7399@172.17.170.150' of Response 12558: Match Not Found
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- ACKing all packets from 15 to (but not including) 17
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- ACKing packet 16, new txqueue is -1 (-1 means empty)
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:20 VERBOSE[3127] logger.c: < N(S): 026 0: 0
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- ACKing all packets from 16 to (but not including) 17
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=5
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 32/0x20) (Terminator)
Jul 20 11:16:20 VERBOSE[3127] logger.c: < Message type: RELEASE COMPLETE (90)
Jul 20 11:16:20 VERBOSE[3127] logger.c: Sending Receiver Ready (27)
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c:
Jul 20 11:16:20 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:20 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:20 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:23 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:23 DEBUG[3049] chan_sip.c: Stopping retransmission on '32f8b2aa8798443c@172.17.170.150' of Response 30967: Match Found
Jul 20 11:16:23 DEBUG[3049] chan_sip.c: Setting NAT on RTP to 524288
Jul 20 11:16:23 DEBUG[3049] chan_sip.c: Checking SIP call limits for device 325
Jul 20 11:16:23 DEBUG[3049] chan_sip.c: build_route: Contact hop: <sip:325@172.17.170.150:36408>
Jul 20 11:16:23 DEBUG[3010] channel.c: Avoiding initial deadlock for 'SIP/325-b7905e28'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Macro("SIP/325-b7905e28", "dialout-trunk|1|96784806||") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK=1") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "_NODEST=") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_NUMBER=96784806") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "ROUTE_PASSWD=") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=tr") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?noauth") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-dialout-trunk,s,8)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "GROUP()=OUT_1") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Macro("SIP/325-b7905e28", "user-callerid|SKIPTTL") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is 'device'
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '325'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing NoOp("SIP/325-b7905e28", "user-callerid: device 325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Noop
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Not taking any branch
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?start") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Not taking any branch
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '325'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: NoOp
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '325'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSER=325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is 'Ryan Williams'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "AMPUSERCIDNAME=Ryan Williams") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Not taking any branch
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=Ryan Williams <325>") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '325'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "REALCALLERIDNUM=325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing NoOp("SIP/325-b7905e28", "TTL: ARG1: SKIPTTL") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Noop
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?continue") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-user-callerid,s,21)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '"Ryan Williams" <325>'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing NoOp("SIP/325-b7905e28", "Using CallerID "Ryan Williams" <325>") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: NoOp
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Macro
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '325'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Macro("SIP/325-b7905e28", "record-enable|325|OUT") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '0'
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?2:4") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-record-enable,s,4)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "recordingcheck|20070720-111623|1184894183.224") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jul 20 11:16:23 VERBOSE[5789] logger.c: recordingcheck|20070720-111623|1184894183.224: Outbound recording not enabled
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- AGI Script recordingcheck completed, returning 0
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing NoOp("SIP/325-b7905e28", "No recording needed") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Noop
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Macro
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?skipoutcid") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Not taking any branch
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "DIAL_TRUNK_OPTIONS=") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Macro("SIP/325-b7905e28", "outbound-callerid|1") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?start") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-outbound-callerid,s,3)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing NoOp("SIP/325-b7905e28", "REALCALLERIDNUM is 325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: NoOp
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?normcid") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-outbound-callerid,s,9)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '243200325'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "USEROUTCID=243200325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] db.c: Unable to find key '325/emergency_cid' in family 'DEVICE'
Jul 20 11:16:23 DEBUG[5789] func_db.c: DB: DEVICE/325/emergency_cid not found in database.
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is ''
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "EMERGENCYCID=") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "TRUNKOUTCID=243200300") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?trunkcid") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-outbound-callerid,s,16)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?usercid") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Not taking any branch
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200300") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?report") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Not taking any branch
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "CALLERID(all)=243200325") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is ''
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?report:hidecid") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-outbound-callerid,s,22)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is '"" <243200325>'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing NoOp("SIP/325-b7905e28", "CallerID set to "" <243200325>") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: NoOp
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Macro
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?nomax") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Goto (macro-dialout-trunk,s,16)
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing DeadAGI("SIP/325-b7905e28", "fixlocalprefix") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Jul 20 11:16:23 VERBOSE[5789] logger.c: == fixlocalprefix: Dialpattern XXXXXXXX matched. 96784806 -> 96784806
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: DeadAGI
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "OUTNUM=96784806") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Function result is 'ZAP/g0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Set("SIP/325-b7905e28", "custom=ZAP/g0") in new stack
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: Set
Jul 20 11:16:23 DEBUG[5789] pbx.c: Expression result is '0'
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "0?customtrunk") in new stack
Jul 20 11:16:23 DEBUG[5789] pbx.c: Not taking any branch
Jul 20 11:16:23 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Executing Dial("SIP/325-b7905e28", "ZAP/g0/96784806|300|") in new stack
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Requested transfer capability: 0x00 - SPEECH
Jul 20 11:16:23 VERBOSE[5789] logger.c:
Jul 20 11:16:23 VERBOSE[5789] logger.c:
Jul 20 11:16:23 VERBOSE[5789] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:23 VERBOSE[5789] logger.c: > N(S): 017 0: 0
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Restarting T203 counter
Jul 20 11:16:23 VERBOSE[5789] logger.c: Stopping T_203 timer
Jul 20 11:16:23 VERBOSE[5789] logger.c: Starting T_200 timer
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Protocol Discriminator: Q.931 (8) len=40
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Call Ref: len= 2 (reference 33/0x21) (Originator)
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Message type: SETUP (5)
Jul 20 11:16:23 VERBOSE[5789] logger.c: > [04 03 80 90 a3]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Ext: 1 User information layer 1: A-Law (35)
Jul 20 11:16:23 VERBOSE[5789] logger.c: > [18 03 a9 83 81]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:23 VERBOSE[5789] logger.c: > ChanSel: Reserved
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Ext: 1 Channel: 1 ]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > [6c 0b 21 80 32 34 33 32 30 30 33 32 35]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Calling Number (len=13) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Presentation: Presentation permitted, user number not screened (0) '243200325' ]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > [70 09 c1 39 36 37 38 34 38 30 36]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Called Number (len=11) [ Ext: 1 TON: Subscriber Number (4) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '96784806' ]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > [a1]
Jul 20 11:16:23 VERBOSE[5789] logger.c: > Sending Complete (len= 1)
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Called g0/96784806
Jul 20 11:16:23 VERBOSE[3127] logger.c:
Jul 20 11:16:23 VERBOSE[3127] logger.c:
Jul 20 11:16:23 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:23 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- ACKing all packets from 16 to (but not including) 18
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- ACKing packet 17, new txqueue is -1 (-1 means empty)
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:23 VERBOSE[3127] logger.c:
Jul 20 11:16:23 VERBOSE[3127] logger.c:
Jul 20 11:16:23 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:23 VERBOSE[3127] logger.c: < N(S): 027 0: 0
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- ACKing all packets from 17 to (but not including) 18
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:23 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=10
Jul 20 11:16:23 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 33/0x21) (Terminator)
Jul 20 11:16:23 VERBOSE[3127] logger.c: < Message type: CALL PROCEEDING (2)
Jul 20 11:16:23 VERBOSE[3127] logger.c: < [18 03 a9 83 81]
Jul 20 11:16:23 VERBOSE[3127] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
Jul 20 11:16:23 VERBOSE[3127] logger.c: < ChanSel: Reserved
Jul 20 11:16:23 VERBOSE[3127] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Jul 20 11:16:23 VERBOSE[3127] logger.c: < Ext: 1 Channel: 1 ]
Jul 20 11:16:23 VERBOSE[3127] logger.c: Sending Receiver Ready (28)
Jul 20 11:16:23 VERBOSE[3127] logger.c:
Jul 20 11:16:23 VERBOSE[3127] logger.c:
Jul 20 11:16:23 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:23 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:23 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:23 DEBUG[3127] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
Jul 20 11:16:23 VERBOSE[5789] logger.c: -- Zap/1-1 is proceeding passing it to SIP/325-b7905e28
Jul 20 11:16:25 VERBOSE[3127] logger.c:
Jul 20 11:16:25 VERBOSE[3127] logger.c:
Jul 20 11:16:25 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:25 VERBOSE[3127] logger.c: < N(S): 028 0: 0
Jul 20 11:16:25 VERBOSE[3127] logger.c: -- ACKing all packets from 17 to (but not including) 18
Jul 20 11:16:25 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:25 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:25 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:25 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=13
Jul 20 11:16:25 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 33/0x21) (Terminator)
Jul 20 11:16:25 VERBOSE[3127] logger.c: < Message type: ALERTING (1)
Jul 20 11:16:25 VERBOSE[3127] logger.c: < [1e 02 80 82]
Jul 20 11:16:25 VERBOSE[3127] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: User (0)
Jul 20 11:16:25 VERBOSE[3127] logger.c: < Ext: 1 Progress Description: Called equipment is non-ISDN. (2) ]
Jul 20 11:16:25 VERBOSE[3127] logger.c: < [1e 02 84 88]
Jul 20 11:16:25 VERBOSE[3127] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the remote user (4)
Jul 20 11:16:25 VERBOSE[3127] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ]
Jul 20 11:16:25 VERBOSE[3127] logger.c: Sending Receiver Ready (29)
Jul 20 11:16:25 VERBOSE[3127] logger.c:
Jul 20 11:16:25 VERBOSE[3127] logger.c:
Jul 20 11:16:25 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:25 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:25 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:25 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:25 DEBUG[3127] chan_zap.c: Enabled echo cancellation on channel 1
Jul 20 11:16:25 VERBOSE[5789] logger.c: -- Zap/1-1 is ringing
Jul 20 11:16:31 VERBOSE[3127] logger.c:
Jul 20 11:16:31 VERBOSE[3127] logger.c:
Jul 20 11:16:31 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:31 VERBOSE[3127] logger.c: < N(S): 029 0: 0
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- ACKing all packets from 17 to (but not including) 18
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:31 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=12
Jul 20 11:16:31 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 33/0x21) (Terminator)
Jul 20 11:16:31 VERBOSE[3127] logger.c: < Message type: CONNECT (7)
Jul 20 11:16:31 VERBOSE[3127] logger.c: < [29 05 07 07 14 0b 10]
Jul 20 11:16:31 VERBOSE[3127] logger.c: < Time Date (len= 7) [ Jul 20 11:16:31 VERBOSE[3127] logger.c: < Time Date (len= 7) [ 07Jul 20 11:16:31 VERBOSE[3127] logger.c: < Time Date (len= 7) [ 07-07Jul 20 11:16:31 VERBOSE[3127] logger.c: < Time Date (len= 7) [ 07-07-20Jul 20 11:16:31 VERBOSE[3127] logger.c: < Time Date (len= 7) [ 07-07-20 11Jul 20 11:16:31 VERBOSE[3127] logger.c: < Time Date (len= 7) [ 07-07-20 11:16Jul 20 11:16:31 VERBOSE[3127] logger.c: < Time Date (len= 7) [ 07-07-20 11:16 ]
Jul 20 11:16:31 VERBOSE[3127] logger.c:
Jul 20 11:16:31 VERBOSE[3127] logger.c:
Jul 20 11:16:31 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:31 VERBOSE[3127] logger.c: > N(S): 018 0: 0
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:31 VERBOSE[3127] logger.c: Stopping T_203 timer
Jul 20 11:16:31 VERBOSE[3127] logger.c: Starting T_200 timer
Jul 20 11:16:31 VERBOSE[3127] logger.c: > Protocol Discriminator: Q.931 (8) len=5
Jul 20 11:16:31 VERBOSE[3127] logger.c: > Call Ref: len= 2 (reference 33/0x21) (Originator)
Jul 20 11:16:31 VERBOSE[3127] logger.c: > Message type: CONNECT ACKNOWLEDGE (15)
Jul 20 11:16:31 DEBUG[3127] chan_zap.c: Echo cancellation already on
Jul 20 11:16:31 VERBOSE[3127] logger.c:
Jul 20 11:16:31 VERBOSE[3127] logger.c:
Jul 20 11:16:31 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:31 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- ACKing all packets from 17 to (but not including) 19
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- ACKing packet 18, new txqueue is -1 (-1 means empty)
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:31 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:31 VERBOSE[5789] logger.c: -- Zap/1-1 answered SIP/325-b7905e28
Jul 20 11:16:31 DEBUG[3010] channel.c: Avoiding initial deadlock for 'SIP/325-b7905e28'
Jul 20 11:16:31 DEBUG[3049] chan_sip.c: Stopping retransmission on '32f8b2aa8798443c@172.17.170.150' of Response 30968: Match Found
Jul 20 11:16:31 VERBOSE[3008] logger.c: -- Remote UNIX connection
Jul 20 11:16:34 NOTICE[3049] chan_sip.c: Registration from '<sip:qx21326@172.17.170.253>' failed for '172.17.170.180' - Username/auth name mismatch
Jul 20 11:16:37 DEBUG[5789] channel.c: Got a FRAME_CONTROL (5) frame on channel Zap/1-1
Jul 20 11:16:37 DEBUG[5789] channel.c: Bridge stops bridging channels SIP/325-b7905e28 and Zap/1-1
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Jul 20 11:16:37 VERBOSE[5789] logger.c:
Jul 20 11:16:37 VERBOSE[5789] logger.c:
Jul 20 11:16:37 VERBOSE[5789] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:37 VERBOSE[5789] logger.c: > N(S): 019 0: 0
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Restarting T203 counter
Jul 20 11:16:37 VERBOSE[5789] logger.c: Stopping T_203 timer
Jul 20 11:16:37 VERBOSE[5789] logger.c: Starting T_200 timer
Jul 20 11:16:37 VERBOSE[5789] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Jul 20 11:16:37 VERBOSE[5789] logger.c: > Call Ref: len= 2 (reference 33/0x21) (Originator)
Jul 20 11:16:37 VERBOSE[5789] logger.c: > Message type: DISCONNECT (69)
Jul 20 11:16:37 VERBOSE[5789] logger.c: > [08 02 81 90]
Jul 20 11:16:37 VERBOSE[5789] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
Jul 20 11:16:37 VERBOSE[5789] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ]
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: Updated conferencing on 1, with 0 conference users
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
Jul 20 11:16:37 DEBUG[5789] chan_zap.c: disabled echo cancellation on channel 1
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Hungup 'Zap/1-1'
Jul 20 11:16:37 DEBUG[5789] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Jul 20 11:16:37 VERBOSE[5789] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/325-b7905e28' in macro 'dialout-trunk'
Jul 20 11:16:37 VERBOSE[5789] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Executing Macro("SIP/325-b7905e28", "hangupcall") in new stack
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Executing ResetCDR("SIP/325-b7905e28", "w") in new stack
Jul 20 11:16:37 DEBUG[5789] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Jul 20 11:16:37 DEBUG[5789] 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) VALUES ('2007-07-20 11:16:23','243200325','243200325','96784806','from-internal', 'SIP/325-b7905e28','Zap/1-1','ResetCDR','w',14,6,'ANSWERED',3,'')
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '243200325'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '243200325'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '96784806'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is 'from-internal'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is 'SIP/325-b7905e28'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is 'Zap/1-1'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is 'ResetCDR'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is 'w'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '2007-07-20 11:16:23'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '2007-07-20 11:16:31'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '2007-07-20 11:16:37'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '14'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '6'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is 'ANSWERED'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is 'DOCUMENTATION'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '(null)'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '1184894183.224'
Jul 20 11:16:37 DEBUG[5789] pbx.c: Function result is '(null)'
Jul 20 11:16:37 DEBUG[5789] app_macro.c: Executed application: ResetCDR
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Executing NoCDR("SIP/325-b7905e28", "") in new stack
Jul 20 11:16:37 NOTICE[5789] cdr.c: CDR on channel 'SIP/325-b7905e28' not posted
Jul 20 11:16:37 NOTICE[5789] cdr.c: CDR on channel 'SIP/325-b7905e28' lacks end
Jul 20 11:16:37 DEBUG[5789] app_macro.c: Executed application: NoCDR
Jul 20 11:16:37 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?skiprg") in new stack
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Goto (macro-hangupcall,s,6)
Jul 20 11:16:37 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:37 DEBUG[5789] pbx.c: Expression result is '1'
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Executing GotoIf("SIP/325-b7905e28", "1?theend") in new stack
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Goto (macro-hangupcall,s,9)
Jul 20 11:16:37 DEBUG[5789] app_macro.c: Executed application: GotoIf
Jul 20 11:16:37 VERBOSE[5789] logger.c: -- Executing Wait("SIP/325-b7905e28", "5") in new stack
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:37 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- ACKing all packets from 18 to (but not including) 20
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- ACKing packet 19, new txqueue is -1 (-1 means empty)
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:37 VERBOSE[3127] logger.c: < N(S): 030 0: 0
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- ACKing all packets from 19 to (but not including) 20
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: < Protocol Discriminator: Q.931 (8) len=5
Jul 20 11:16:37 VERBOSE[3127] logger.c: < Call Ref: len= 2 (reference 33/0x21) (Terminator)
Jul 20 11:16:37 VERBOSE[3127] logger.c: < Message type: RELEASE (77)
Jul 20 11:16:37 VERBOSE[3127] logger.c: Sending Receiver Ready (31)
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:37 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:37 VERBOSE[3127] logger.c: > N(S): 020 0: 0
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: Stopping T_203 timer
Jul 20 11:16:37 VERBOSE[3127] logger.c: Starting T_200 timer
Jul 20 11:16:37 VERBOSE[3127] logger.c: > Protocol Discriminator: Q.931 (8) len=9
Jul 20 11:16:37 VERBOSE[3127] logger.c: > Call Ref: len= 2 (reference 33/0x21) (Originator)
Jul 20 11:16:37 VERBOSE[3127] logger.c: > Message type: RELEASE COMPLETE (90)
Jul 20 11:16:37 VERBOSE[3127] logger.c: > [08 02 81 90]
Jul 20 11:16:37 VERBOSE[3127] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
Jul 20 11:16:37 VERBOSE[3127] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ]
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c:
Jul 20 11:16:37 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 0 EA: 0
Jul 20 11:16:37 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- ACKing all packets from 19 to (but not including) 21
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- ACKing packet 20, new txqueue is -1 (-1 means empty)
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:37 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:42 DEBUG[5789] app_macro.c: Executed application: Wait
Jul 20 11:16:42 VERBOSE[5789] logger.c: -- Executing Hangup("SIP/325-b7905e28", "") in new stack
Jul 20 11:16:42 VERBOSE[5789] logger.c: == Spawn extension (macro-hangupcall, s, 10) exited non-zero on 'SIP/325-b7905e28' in macro 'hangupcall'
Jul 20 11:16:42 VERBOSE[5789] logger.c: == Spawn extension (macro-hangupcall, s, 10) exited non-zero on 'SIP/325-b7905e28'
Jul 20 11:16:42 DEBUG[5789] chan_sip.c: update_call_counter(325) - decrement call limit counter
Jul 20 11:16:42 DEBUG[3049] chan_sip.c: Stopping retransmission on '32f8b2aa8798443c@172.17.170.150' of Request 102: Match Found
Jul 20 11:16:47 VERBOSE[3127] logger.c:
Jul 20 11:16:47 VERBOSE[3127] logger.c:
Jul 20 11:16:47 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:47 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:47 VERBOSE[3127] logger.c: -- ACKing all packets from 20 to (but not including) 21
Jul 20 11:16:47 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:47 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:47 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:47 VERBOSE[3127] logger.c: -- Unsolicited RR with P/F bit, responding
Jul 20 11:16:47 VERBOSE[3127] logger.c: Sending Receiver Ready (31)
Jul 20 11:16:47 VERBOSE[3127] logger.c:
Jul 20 11:16:47 VERBOSE[3127] logger.c:
Jul 20 11:16:47 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:47 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:47 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:47 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:49 DEBUG[3049] chan_sip.c: Auto destroying call 'ADC1D620-9FBC-45EC-9EC6-06E51E6AF77F@172.17.170.180'
Jul 20 11:16:53 VERBOSE[5799] logger.c: -- Remote UNIX connection disconnected
Jul 20 11:16:57 VERBOSE[3127] logger.c:
Jul 20 11:16:57 VERBOSE[3127] logger.c:
Jul 20 11:16:57 VERBOSE[3127] logger.c: < SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:57 VERBOSE[3127] logger.c: < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:57 VERBOSE[3127] logger.c: -- ACKing all packets from 20 to (but not including) 21
Jul 20 11:16:57 VERBOSE[3127] logger.c: -- Since there was nothing left, stopping T200 counter
Jul 20 11:16:57 VERBOSE[3127] logger.c: -- Stopping T203 counter since we got an ACK
Jul 20 11:16:57 VERBOSE[3127] logger.c: -- Nothing left, starting T203 counter
Jul 20 11:16:57 VERBOSE[3127] logger.c: -- Unsolicited RR with P/F bit, responding
Jul 20 11:16:57 VERBOSE[3127] logger.c: Sending Receiver Ready (31)
Jul 20 11:16:57 VERBOSE[3127] logger.c:
Jul 20 11:16:57 VERBOSE[3127] logger.c:
Jul 20 11:16:57 VERBOSE[3127] logger.c: > SAPI: 00 C/R: 1 EA: 0
Jul 20 11:16:57 VERBOSE[3127] logger.c: > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
Jul 20 11:16:57 VERBOSE[3127] logger.c: -- Restarting T203 counter
Jul 20 11:16:57 VERBOSE[3127] logger.c: -- Restarting T203 counter
[root@pbx asterisk]#