Jul 2 12:43:13 VERBOSE[26444] logger.c: -- Remote UNIX connection Jul 2 12:43:18 NOTICE[26453] chan_iax2.c: Peer 'dhn-sra' is not dynamic (from 10.60.34.101) Jul 2 12:43:22 DEBUG[26453] chan_iax2.c: Peer lastms 13, historicms 13, maxms 2000 Jul 2 12:43:24 DEBUG[26453] chan_iax2.c: Peer lastms 26, historicms 26, maxms 2000 Jul 2 12:43:24 DEBUG[26453] chan_iax2.c: Peer lastms 20, historicms 20, maxms 2000 Jul 2 12:43:25 DEBUG[26458] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Jul 2 12:43:25 DEBUG[26458] chan_sip.c: Stopping retransmission on '4ef5333e3944687f4c8329ad2d8d60fd@10.60.33.102' of Request 102: Match Found Jul 2 12:43:28 DEBUG[26780] manager.c: Manager received command 'Command' Jul 2 12:43:28 DEBUG[26780] manager.c: Manager received command 'Command' Jul 2 12:43:29 DEBUG[26458] chan_sip.c: Allocating new SIP dialog for 3c41e8f70753-g2jc9ect6xxe@snom190 - INVITE (With RTP) Jul 2 12:43:29 DEBUG[26458] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Jul 2 12:43:29 DEBUG[26458] chan_sip.c: * SIP extension value: 7 for call 3c41e8f70753-g2jc9ect6xxe@snom190 Jul 2 12:43:29 DEBUG[26458] chan_sip.c: Setting NAT on RTP to 0 Jul 2 12:43:29 DEBUG[26458] chan_sip.c: Checking SIP call limits for device 309 Jul 2 12:43:29 DEBUG[26458] chan_sip.c: Updating call counter for incoming call Jul 2 12:43:29 DEBUG[26458] chan_sip.c: build_route: Contact hop: Jul 2 12:43:29 DEBUG[26446] chan_sip.c: Checking device state for peer 309 Jul 2 12:43:29 DEBUG[26446] channel.c: Avoiding initial deadlock for 'SIP/309-4a88' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Macro' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Macro("SIP/309-4a88", "dialout-trunk|4|0400518501||") in new stack Jul 2 12:43:29 DEBUG[26446] devicestate.c: Changing state for SIP/309 - state 2 (In use) Jul 2 12:43:29 DEBUG[26446] chan_sip.c: Checking device state for peer 309 Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '1' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "1?3:2") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Goto (macro-dialout-trunk,s,3) Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Macro' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Macro("SIP/309-4a88", "user-callerid") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '0' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "0?report") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Not taking any branch Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '0' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "0?start") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Not taking any branch Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '309' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "REALCALLERIDNUM=309") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'NoOp' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing NoOp("SIP/309-4a88", "REALCALLERIDNUM is 309") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '309' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "AMPUSER=309") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is 'Darren' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "AMPUSERCIDNAME=Darren") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '0' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "0?report") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Not taking any branch Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "CALLERID(all)=Darren <309>") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '"Darren" <309>' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'NoOp' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing NoOp("SIP/309-4a88", "Using CallerID "Darren" <309>") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '309' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Macro' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Macro("SIP/309-4a88", "record-enable|309|OUT") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '0' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "0 > 0?2:4") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Goto (macro-record-enable,s,4) Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'AGI' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing AGI("SIP/309-4a88", "recordingcheck|20060702-124329|1151815409.70") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Jul 2 12:43:29 DEBUG[27029] app_queue.c: Device 'SIP/309' changed to state '2' (In use) Jul 2 12:43:29 VERBOSE[27028] logger.c: recordingcheck|20060702-124329|1151815409.70: Outbound recording not enabled Jul 2 12:43:29 VERBOSE[27028] logger.c: -- AGI Script recordingcheck completed, returning 0 Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'NoOp' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing NoOp("SIP/309-4a88", "No recording needed") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Macro' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Macro("SIP/309-4a88", "outbound-callerid|4") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '1' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "1?start") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Goto (macro-outbound-callerid,s,3) Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'NoOp' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing NoOp("SIP/309-4a88", "REALCALLERIDNUM is 309") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "USEROUTCID=") in new stack Jul 2 12:43:29 DEBUG[27028] db.c: Unable to find key '309/emergency_cid' in family 'DEVICE' Jul 2 12:43:29 DEBUG[27028] func_db.c: DB: DEVICE/309/emergency_cid not found in database. Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "EMERGENCYCID=") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "TRUNKOUTCID=") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '1' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "1?trunkcid") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Goto (macro-outbound-callerid,s,11) Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '1' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "1?usercid") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Goto (macro-outbound-callerid,s,13) Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '1' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "1?report") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Goto (macro-outbound-callerid,s,15) Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '"Darren" <309>' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'NoOp' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing NoOp("SIP/309-4a88", "CallerID set to "Darren" <309>") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "GROUP()=OUT_4") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is '1' Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '0' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "0?108") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Not taking any branch Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "DIAL_NUMBER=0400518501") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "DIAL_TRUNK=4") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'AGI' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing AGI("SIP/309-4a88", "fixlocalprefix") in new stack Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix Jul 2 12:43:29 VERBOSE[27028] logger.c: fixlocalprefix: Could not parse /etc/asterisk/localprefixes.conf Jul 2 12:43:29 VERBOSE[27028] logger.c: -- AGI Script fixlocalprefix completed, returning 0 Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "OUTNUM=0400518501") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Function result is 'ZAP/4' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Set' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Set("SIP/309-4a88", "custom=ZAP/4") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Expression result is '0' Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'GotoIf' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing GotoIf("SIP/309-4a88", "0?16") in new stack Jul 2 12:43:29 DEBUG[27028] pbx.c: Not taking any branch Jul 2 12:43:29 DEBUG[27028] pbx.c: Launching 'Dial' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Executing Dial("SIP/309-4a88", "ZAP/4/0400518501|120|r") in new stack Jul 2 12:43:29 DEBUG[27028] chan_zap.c: Using channel 4 Jul 2 12:43:29 DEBUG[26446] devicestate.c: Changing state for Zap/4 - state 2 (In use) Jul 2 12:43:29 DEBUG[27032] app_queue.c: Device 'Zap/4' changed to state '2' (In use) Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-14. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable MACRO_DEPTH. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-13. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable custom. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-12. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable OUTNUM. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-11. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-10. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable DIAL_TRUNK. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-9. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable DIAL_NUMBER. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-8. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-7. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable GROUP. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-6. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable MACRO_PRIORITY. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable MACRO_CONTEXT. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable MACRO_EXTEN. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable ARG1. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-15. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-13. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-11. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-7. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable TRUNKOUTCID. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-6. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable EMERGENCYCID. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-5. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable USEROUTCID. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-4. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable DB_RESULT. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-3. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-outbound-callerid-s-1. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-5. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable ARG2. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-record-enable-s-5. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-record-enable-s-4. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-record-enable-s-1. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-4. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-9. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-8. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-7. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable AMPUSERCIDNAME. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-6. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable AMPUSER. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-5. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-4. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable REALCALLERIDNUM. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-3. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-2. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-user-callerid-s-1. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-3. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-macro-dialout-trunk-s-1. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable ARG4. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable ARG3. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable STACK-from-internal-0400518501-1. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable SIPCALLID. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable SIPUSERAGENT. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable SIPDOMAIN. Jul 2 12:43:29 DEBUG[27028] channel.c: Not copying variable SIPURI. Jul 2 12:43:29 DEBUG[27028] chan_zap.c: Dialing '0400518501' Jul 2 12:43:29 DEBUG[27028] chan_zap.c: Deferring dialing... Jul 2 12:43:29 DEBUG[26446] channel.c: Avoiding initial deadlock for 'Zap/4-1' Jul 2 12:43:29 VERBOSE[27028] logger.c: -- Called 4/0400518501 Jul 2 12:43:29 DEBUG[26446] devicestate.c: Changing state for Zap/4 - state 2 (In use) Jul 2 12:43:29 DEBUG[27033] app_queue.c: Device 'Zap/4' changed to state '2' (In use) Jul 2 12:43:30 DEBUG[27028] chan_zap.c: Exception on 16, channel 4 Jul 2 12:43:30 DEBUG[27028] chan_zap.c: Got event Hook Transition Complete(12) on channel 4 (index 0) Jul 2 12:43:31 DEBUG[26453] chan_iax2.c: Allocate call number Jul 2 12:43:31 DEBUG[26453] chan_iax2.c: Registration created on call 5 Jul 2 12:43:32 DEBUG[27028] chan_zap.c: Exception on 16, channel 4 Jul 2 12:43:32 DEBUG[27028] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0) Jul 2 12:43:32 DEBUG[27028] chan_zap.c: Enabled echo cancellation on channel 4 Jul 2 12:43:32 DEBUG[27028] chan_zap.c: Engaged echo training on channel 4 Jul 2 12:43:32 NOTICE[26453] chan_iax2.c: Registration of 'sra-dhn' rejected: 'Registration Refused' from: '10.60.34.101' Jul 2 12:43:34 DEBUG[27028] chan_zap.c: Exception on 16, channel 4 Jul 2 12:43:34 DEBUG[27028] chan_zap.c: Got event Dial Complete(9) on channel 4 (index 0) Jul 2 12:43:34 DEBUG[27028] chan_zap.c: Echo cancellation already on Jul 2 12:43:34 DEBUG[26446] channel.c: Avoiding initial deadlock for 'Zap/4-1' Jul 2 12:43:34 VERBOSE[27028] logger.c: -- Zap/4-1 answered SIP/309-4a88 Jul 2 12:43:34 DEBUG[27028] channel.c: Set channel SIP/309-4a88 to read format ulaw Jul 2 12:43:34 DEBUG[27028] channel.c: Set channel Zap/4-1 to write format ulaw Jul 2 12:43:34 DEBUG[27028] channel.c: Set channel Zap/4-1 to read format ulaw Jul 2 12:43:34 DEBUG[27028] channel.c: Set channel SIP/309-4a88 to write format ulaw Jul 2 12:43:34 DEBUG[27028] chan_sip.c: sip_answer(SIP/309-4a88) Jul 2 12:43:34 DEBUG[26446] devicestate.c: Changing state for Zap/4 - state 2 (In use) Jul 2 12:43:34 DEBUG[26446] chan_sip.c: Checking device state for peer 309 Jul 2 12:43:34 DEBUG[26446] devicestate.c: Changing state for SIP/309 - state 2 (In use) Jul 2 12:43:34 DEBUG[26446] chan_sip.c: Checking device state for peer 309 Jul 2 12:43:34 DEBUG[27034] app_queue.c: Device 'Zap/4' changed to state '2' (In use) Jul 2 12:43:34 DEBUG[27035] app_queue.c: Device 'SIP/309' changed to state '2' (In use) Jul 2 12:43:34 DEBUG[27028] rtp.c: Ooh, format changed from unknown to ulaw Jul 2 12:43:34 DEBUG[26458] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Jul 2 12:43:34 DEBUG[26458] chan_sip.c: Stopping retransmission on '3c41e8f70753-g2jc9ect6xxe@snom190' of Response 1: Match Found Jul 2 12:43:35 DEBUG[26453] chan_iax2.c: Allocate call number Jul 2 12:43:35 DEBUG[26453] chan_iax2.c: Registration created on call 6 Jul 2 12:43:50 DEBUG[26453] chan_iax2.c: Packet arrived out of order (expecting 1, got 0) (frametype = 6, subclass = 30) Jul 2 12:43:50 DEBUG[26453] chan_iax2.c: Acking anyway Jul 2 12:43:51 DEBUG[26458] chan_sip.c: **** Received BYE (8) - Command in SIP BYE Jul 2 12:43:51 DEBUG[27028] channel.c: Didn't get a frame from channel: SIP/309-4a88 Jul 2 12:43:51 DEBUG[27028] channel.c: Bridge stops bridging channels SIP/309-4a88 and Zap/4-1 Jul 2 12:43:51 DEBUG[27028] channel.c: Hanging up channel 'Zap/4-1' Jul 2 12:43:51 DEBUG[27028] chan_zap.c: zt_hangup(Zap/4-1) Jul 2 12:43:51 DEBUG[27028] chan_zap.c: Hangup: channel: 4 index = 0, normal = 16, callwait = -1, thirdcall = -1 Jul 2 12:43:51 DEBUG[27028] chan_zap.c: disabled echo cancellation on channel 4 Jul 2 12:43:51 DEBUG[27028] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/4-1 Jul 2 12:43:51 DEBUG[27028] chan_zap.c: Updated conferencing on 4, with 0 conference users Jul 2 12:43:51 VERBOSE[27028] logger.c: -- Hungup 'Zap/4-1' Jul 2 12:43:51 DEBUG[27028] app_dial.c: Exiting with DIALSTATUS=ANSWER. Jul 2 12:43:51 DEBUG[27028] app_macro.c: Spawn extension (macro-dialout-trunk,s,14) exited non-zero on 'SIP/309-4a88' in macro 'dialout-trunk' Jul 2 12:43:51 DEBUG[27028] pbx.c: Spawn extension (macro-dialout-trunk,s,14) exited non-zero on 'SIP/309-4a88' Jul 2 12:43:51 DEBUG[27028] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Jul 2 12:43:51 DEBUG[27028] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2006-07-02 12:43:29','\"Darren\" <309>','309','0400518501','from-internal', 'SIP/309-4a88','Zap/4-1','Dial','ZAP/4/0400518501|120|r',22,17,'ANSWERED',3,'','1151815409.70') Jul 2 12:43:51 DEBUG[27028] channel.c: Hanging up channel 'SIP/309-4a88' Jul 2 12:43:51 DEBUG[27028] chan_sip.c: Hangup call SIP/309-4a88, SIP callid 3c41e8f70753-g2jc9ect6xxe@snom190) Jul 2 12:43:51 DEBUG[27028] chan_sip.c: update_call_counter(309) - decrement call limit counter Jul 2 12:43:51 DEBUG[27028] chan_sip.c: Updating call counter for incoming call Jul 2 12:43:51 DEBUG[26446] devicestate.c: Changing state for Zap/4 - state 0 (Unknown) Jul 2 12:43:51 DEBUG[26446] chan_sip.c: Checking device state for peer 309 Jul 2 12:43:51 DEBUG[26446] devicestate.c: Changing state for SIP/309 - state 1 (Not in use) Jul 2 12:43:51 DEBUG[26446] chan_sip.c: Checking device state for peer 309 Jul 2 12:43:51 DEBUG[27036] app_queue.c: Device 'Zap/4' changed to state '0' (Unknown) Jul 2 12:43:51 DEBUG[27037] app_queue.c: Device 'SIP/309' changed to state '1' (Not in use) Jul 2 12:44:08 NOTICE[26453] chan_iax2.c: Peer 'dhn-sra' is not dynamic (from 10.60.34.101) Jul 2 12:44:21 DEBUG[26453] chan_iax2.c: Allocate call number Jul 2 12:44:21 DEBUG[26453] chan_iax2.c: Registration created on call 4 Jul 2 12:44:22 NOTICE[26453] chan_iax2.c: Registration of 'sra-dhn' rejected: 'Registration Refused' from: '10.60.34.101' Jul 2 12:44:22 DEBUG[26453] chan_iax2.c: Peer lastms 13, historicms 13, maxms 2000 Jul 2 12:44:24 DEBUG[26453] chan_iax2.c: Peer lastms 26, historicms 26, maxms 2000 Jul 2 12:44:24 DEBUG[26453] chan_iax2.c: Peer lastms 19, historicms 19, maxms 2000 Jul 2 12:44:25 DEBUG[26458] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Jul 2 12:44:25 DEBUG[26458] chan_sip.c: Stopping retransmission on '3836c78614b8425c146478ba66e4f869@10.60.33.102' of Request 102: Match Found Jul 2 12:44:25 DEBUG[26453] chan_iax2.c: Allocate call number Jul 2 12:44:25 DEBUG[26453] chan_iax2.c: Registration created on call 8 Jul 2 12:44:58 NOTICE[26453] chan_iax2.c: Peer 'dhn-sra' is not dynamic (from 10.60.34.101) Jul 2 12:45:11 DEBUG[26453] chan_iax2.c: Allocate call number Jul 2 12:45:11 DEBUG[26453] chan_iax2.c: Registration created on call 3 Jul 2 12:45:12 NOTICE[26453] chan_iax2.c: Registration of 'sra-dhn' rejected: 'Registration Refused' from: '10.60.34.101' Jul 2 12:45:15 DEBUG[26453] chan_iax2.c: Allocate call number Jul 2 12:45:15 DEBUG[26453] chan_iax2.c: Registration created on call 13