== Manager registered action DBGet == Manager registered action DBPut == Parsing '/etc/asterisk/enum.conf': Found Asterisk Ready. *CLI> *CLI> *CLI> *CLI> set debug 4 Core debug was 0 and is now 4 *CLI> ooh323 debug OOH323 Debugging Enabled *CLI> --- onNewCallCreated ooh323c_1 +++ onNewCallCreated ooh323c_1 --- ooh323_onReceivedSetup ooh323c_1 Jul 10 19:32:49 DEBUG[1921]: src/chan_h323.c:358 ooh323_alloc: --- ooh323_alloc Jul 10 19:32:49 DEBUG[1921]: src/chan_h323.c:441 ooh323_alloc: +++ ooh323_alloc --- find_user +++ find_user Adding capabilities to call(incoming, ooh323c_1) Adding g711 ulaw capability to call(incoming, ooh323c_1) --- configure_local_rtp +++ configure_local_rtp +++ ooh323_onReceivedSetup - Determined context default, extension 6111 --- onAlerting ooh323c_1 --- find_call +++ find_call Jul 10 19:32:50 DEBUG[1921]: src/chan_h323.c:240 ooh323_new: --- ooh323_new - ken_op Jul 10 19:32:50 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'OOH323/ken_op-a00e' Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("OOH323/ken_op-a00e", "exten-vm|novm|6111") in new stack Jul 10 19:32:50 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'OOH323/ken_op-a00e' Jul 10 19:32:50 DEBUG[1921]: src/chan_h323.c:346 ooh323_new: +++ h323_new +++ onAlerting ooh323c_1 Jul 10 19:32:50 DEBUG[1903]: devicestate.c:187 do_state_change: Changing state for OOH323/ken_op - state 2 (In use) Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("OOH323/ken_op-a00e", "user-callerid") in new stack Jul 10 19:32:50 DEBUG[1926]: app_queue.c:523 changethread: Device 'OOH323/ken_op' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jul 10 19:32:50 DEBUG[1925]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("OOH323/ken_op-a00e", "0?report") in new stack Jul 10 19:32:50 DEBUG[1925]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jul 10 19:32:50 DEBUG[1925]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("OOH323/ken_op-a00e", "0?start") in new stack Jul 10 19:32:50 DEBUG[1925]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jul 10 19:32:50 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '' Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "REALCALLERIDNUM=") in new stack Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("OOH323/ken_op-a00e", "REALCALLERIDNUM is ") in new stack Jul 10 19:32:50 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '/user' in family 'DEVICE' Jul 10 19:32:50 DEBUG[1925]: func_db.c:69 function_db_read: DB: DEVICE//user not found in database. Jul 10 19:32:50 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '' Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "AMPUSER=") in new stack Jul 10 19:32:50 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '/cidname' in family 'AMPUSER' Jul 10 19:32:50 DEBUG[1925]: func_db.c:69 function_db_read: DB: AMPUSER//cidname not found in database. Jul 10 19:32:50 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '' Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "AMPUSERCIDNAME=") in new stack Jul 10 19:32:50 DEBUG[1925]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '1' Jul 10 19:32:50 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("OOH323/ken_op-a00e", "1?report") in new stack -- Goto (macro-user-callerid,s,9) Jul 10 19:32:51 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"ken_op" <>' Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("OOH323/ken_op-a00e", "Using CallerID "ken_op" <>") in new stack Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "FROMCONTEXT=exten-vm") in new stack Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "VMBOX=novm") in new stack Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "EXTTOCALL=6111") in new stack Jul 10 19:32:51 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '6111' in family 'CFU' Jul 10 19:32:51 DEBUG[1925]: func_db.c:69 function_db_read: DB: CFU/6111 not found in database. Jul 10 19:32:51 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '' Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "CFUEXT=") in new stack Jul 10 19:32:51 DEBUG[1925]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 19:32:51 DEBUG[1925]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 19:32:51 DEBUG[1925]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 19:32:51 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '' Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("OOH323/ken_op-a00e", "RT=") in new stack Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("OOH323/ken_op-a00e", "record-enable|6111|IN") in new stack Jul 10 19:32:51 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("OOH323/ken_op-a00e", "0 > 0?2:4") in new stack -- Goto (macro-record-enable,s,4) Jul 10 19:32:51 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'AGI' -- Executing AGI("OOH323/ken_op-a00e", "recordingcheck|20060710-193251|1152559970.0") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck recordingcheck|20060710-193251|1152559970.0: Inbound recording not enabled -- AGI Script recordingcheck completed, returning 0 Jul 10 19:32:52 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("OOH323/ken_op-a00e", "No recording needed") in new stack Jul 10 19:32:52 DEBUG[1925]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 19:32:52 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("OOH323/ken_op-a00e", "0?dolocaldial|1") in new stack Jul 10 19:32:52 DEBUG[1925]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jul 10 19:32:52 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("OOH323/ken_op-a00e", "dial|||6111") in new stack Jul 10 19:32:52 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'AGI' -- Executing AGI("OOH323/ken_op-a00e", "dialparties.agi") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi dialparties.agi: Starting New Dialparties.agi -- dialparties.agi: priority is 1 dialparties.agi: Caller ID name is 'ken_op' number is 'unknown' dialparties.agi: Methodology of ring is 'none' -- dialparties.agi: Added extension 6111 to extension map Jul 10 19:32:53 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '6111' in family 'CF' -- dialparties.agi: Extension 6111 cf is disabled Jul 10 19:32:53 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '6111' in family 'DND' -- dialparties.agi: Extension 6111 do not disturb is disabled Jul 10 19:32:53 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '6111' in family 'CW' Jul 10 19:32:53 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '6111' in family 'CFB' Jul 10 19:32:53 DEBUG[1925]: db.c:200 ast_db_get: Unable to find key '6111' in family 'CFU' Jul 10 19:32:53 DEBUG[1929]: manager.c:1249 process_message: Manager received command 'login' Jul 10 19:32:54 DEBUG[1929]: config.c:595 config_text_file_load: Parsing /etc/asterisk/manager.conf Jul 10 19:32:54 DEBUG[1929]: acl.c:199 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Jul 10 19:32:54 DEBUG[1929]: acl.c:199 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Jul 10 19:32:54 DEBUG[1929]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0 Jul 10 19:32:54 DEBUG[1929]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0 == Manager 'ken' logged on from 127.0.0.1 Jul 10 19:32:54 DEBUG[1929]: manager.c:1249 process_message: Manager received command 'ExtensionState' Jul 10 19:32:54 DEBUG[1929]: chan_sip.c:11717 sip_devicestate: Checking device state for peer 6111 Jul 10 19:32:54 DEBUG[1929]: manager.c:1249 process_message: Manager received command 'Logoff' == Manager 'ken' logged off from 127.0.0.1 -- dialparties.agi: Checking CW and CFB status for extension 6111 -- dialparties.agi: DbSet CALLTRACE/6111 to unknown -- AGI Script dialparties.agi completed, returning 0 Jul 10 19:32:55 DEBUG[1925]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("OOH323/ken_op-a00e", "SIP/6111||") in new stack Jul 10 19:32:55 DEBUG[1925]: chan_sip.c:3192 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Jul 10 19:32:55 DEBUG[1925]: chan_sip.c:1874 create_addr_from_peer: Setting NAT on RTP to 0 Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ds. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ARG3. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ARG2. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ARG1. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-9. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-8. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-5. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-4. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-1. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-7. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable RT. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-6. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable CFUEXT. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-5. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable EXTTOCALL. Jul 10 19:32:55 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-4. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable VMBOX. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-3. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable FROMCONTEXT. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-2. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-9. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-7. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-6. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable AMPUSER. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-5. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-4. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-3. Jul 10 19:32:56 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-2. Jul 10 19:32:57 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-1. Jul 10 19:32:57 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-1. Jul 10 19:32:57 DEBUG[1925]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-default-6111-1. Jul 10 19:32:57 DEBUG[1925]: channel.c:2816 ast_channel_inherit_variables: Copying soft-transferable variable CALLER_H323ID. Jul 10 19:32:57 DEBUG[1925]: chan_sip.c:2068 sip_call: Outgoing Call for 6111 Jul 10 19:32:57 DEBUG[1925]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call -- Called 6111 Jul 10 19:32:57 DEBUG[1915]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' Request 102: Found Jul 10 19:32:57 DEBUG[1915]: chan_sip.c:9633 handle_response_invite: SIP response 100 to standard invite Jul 10 19:32:57 DEBUG[1915]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' Request 102: Found Jul 10 19:32:57 DEBUG[1915]: chan_sip.c:9633 handle_response_invite: SIP response 180 to standard invite Jul 10 19:32:57 DEBUG[1903]: chan_sip.c:11717 sip_devicestate: Checking device state for peer 6111 Jul 10 19:32:57 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6111-cbe1' -- ast_channel_make_compatible: src=0x4: dst=0x4 Jul 10 19:32:57 DEBUG[1925]: channel.c:2350 set_format: Set channel SIP/6111-cbe1 to read format ulaw Jul 10 19:32:57 DEBUG[1903]: devicestate.c:187 do_state_change: Changing state for SIP/6111 - state 6 (Ringing) Jul 10 19:32:57 DEBUG[1903]: chan_sip.c:11717 sip_devicestate: Checking device state for peer 6111 Jul 10 19:32:57 DEBUG[1930]: app_queue.c:523 changethread: Device 'SIP/6111' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. Jul 10 19:32:57 DEBUG[1925]: channel.c:2350 set_format: Set channel OOH323/ken_op-a00e to write format ulaw Jul 10 19:32:57 DEBUG[1925]: channel.c:2350 set_format: Set channel OOH323/ken_op-a00e to read format ulaw Jul 10 19:32:58 DEBUG[1925]: channel.c:2350 set_format: Set channel SIP/6111-cbe1 to write format ulaw -- SIP/6111-cbe1 is ringing ----- ooh323_indicate 3 on call ooh323c_1 ++++ ooh323_indicate 3 on ooh323c_1 Jul 10 19:32:58 DEBUG[1925]: channel.c:2036 ast_indicate: Driver for channel 'OOH323/ken_op-a00e' does not support indication 3, emulating it Jul 10 19:32:58 DEBUG[1925]: channel.c:2167 ast_prod: Prodding channel 'OOH323/ken_op-a00e' Jul 10 19:32:58 DEBUG[1925]: channel.c:2350 set_format: Set channel OOH323/ken_op-a00e to write format slin Jul 10 19:32:58 DEBUG[1915]: chan_sip.c:1379 __sip_ack: Acked pending invite 102 Jul 10 19:32:58 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 102: Match Found *CLI> *CLI> *CLI> Jul 10 19:32:58 DEBUG[1915]: chan_sip.c:9633 handle_response_invite: SIP response 200 to standard invite Jul 10 19:33:06 DEBUG[1915]: chan_sip.c:6186 build_route: build_route: Contact hop: -- SIP/6111-cbe1 answered OOH323/ken_op-a00e Jul 10 19:33:06 DEBUG[1903]: chan_sip.c:11717 sip_devicestate: Checking device state for peer 6111 ----- ooh323_indicate -1 on call ooh323c_1:187 do_state_change: Changing state for SIP/6111 - state 2 (In use) Jul 10 19:33:06 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 102: Match Not Found Jul 10 19:33:06 DEBUG[1931]: app_queue.c:523 changethread: Device 'SIP/6111' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jul 10 19:33:06 DEBUG[1903]: chan_sip.c:11717 sip_devicestate: Checking device state for peer 6111 Jul 10 19:33:06 WARNING[1925]: src/chan_h323.c:951 ooh323_indicate: Don't know how to indicate condition -1 on ooh323c_1 ++++ ooh323_indicate -1 on ooh323c_1 Jul 10 19:33:06 DEBUG[1915]: chan_sip.c:9631 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239 Jul 10 19:33:06 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6111-cbe1' Jul 10 19:33:06 DEBUG[1925]: channel.c:2350 set_format: Set channel OOH323/ken_op-a00e to write format ulaw -- ast_channel_make_compatible: src=0x4: dst=0x4 Jul 10 19:33:06 DEBUG[1915]: chan_sip.c:6129 build_route: build_route: Retaining previous route: Jul 10 19:33:06 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6111-cbe1' Jul 10 19:33:06 DEBUG[1925]: channel.c:2350 set_format: Set channel OOH323/ken_op-a00e to read format ulaw Jul 10 19:33:06 DEBUG[1925]: channel.c:2350 set_format: Set channel SIP/6111-cbe1 to write format ulaw Jul 10 19:33:06 DEBUG[1925]: channel.c:2350 set_format: Set channel SIP/6111-cbe1 to read format ulaw Jul 10 19:33:06 DEBUG[1925]: channel.c:2350 set_format: Set channel OOH323/ken_op-a00e to write format ulaw --- ooh323_answer Jul 10 19:33:06 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 102: Match Not Found Jul 10 19:33:06 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'OOH323/ken_op-a00e' Jul 10 19:33:06 DEBUG[1925]: src/chan_h323.c:844 ooh323_answer: ooh323_answer(OOH323/ken_op-a00e) +++ ooh323_answer Jul 10 19:33:07 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'OOH323/ken_op-a00e' --- onCallEstablished ooh323c_1 --- find_call +++ find_call Jul 10 19:33:07 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'OOH323/ken_op-a00e' Jul 10 19:33:07 DEBUG[1903]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'OOH323/ken_op-a00e' -- ast_channel_bridge is being called: (1) flags=0x0 Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:9631 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239 Jul 10 19:33:07 DEBUG[1903]: devicestate.c:187 do_state_change: Changing state for OOH323/ken_op - state 2 (In use) +++ onCallEstablished ooh323c_1 Jul 10 19:33:07 DEBUG[1932]: app_queue.c:523 changethread: Device 'OOH323/ken_op' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:6129 build_route: build_route: Retaining previous route: -- ast_channel_bridge is being called: (2) c0-bridge=268845316: c1-bridge=268845316 -- Attempting native bridge of OOH323/ken_op-a00e and SIP/6111-cbe1 Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 102: Match Not Found Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:9631 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239 Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:6129 build_route: build_route: Retaining previous route: --- ooh323_set_peer - OOH323/ken_op-a00e Jul 10 19:33:07 DEBUG[1925]: chan_sip.c:12971 sip_set_rtp_peer: Sending reinvite on SIP '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' - It's audio soon redirected to IP 0.0.0.0 Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:1379 __sip_ack: Acked pending invite 103 Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 103: Match Found Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:9631 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239 Jul 10 19:33:07 DEBUG[1915]: chan_sip.c:6129 build_route: build_route: Retaining previous route: == Forcing Marker bit, because SSRC has changed == Forcing Marker bit, because SSRC has changed == Forcing Marker bit, because SSRC has changed == Forcing Marker bit, because SSRC has changed --- setup_rtp_connection --- find_call +++ find_call +++ setup_rtp_connection Jul 10 19:33:09 DEBUG[1925]: rtp.c:1378 ast_rtp_write: Ooh, format changed from unknown to ulaw Jul 10 19:33:09 DEBUG[1925]: rtp.c:1756 ast_rtp_bridge: Oooh, 'OOH323/ken_op-a00e' changed end address to 10.1.1.155:1720 (format 0) Jul 10 19:33:09 DEBUG[1925]: rtp.c:1758 ast_rtp_bridge: Oooh, 'OOH323/ken_op-a00e' was 0.0.0.0:0/(format 0) Jul 10 19:33:09 DEBUG[1925]: chan_sip.c:12971 sip_set_rtp_peer: Sending reinvite on SIP '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' - It's audio soon redirected to IP 10.1.1.155 Jul 10 19:33:09 DEBUG[1915]: chan_sip.c:1379 __sip_ack: Acked pending invite 104 Jul 10 19:33:09 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 104: Match Found Jul 10 19:33:09 DEBUG[1915]: chan_sip.c:9631 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239 Jul 10 19:33:09 DEBUG[1915]: chan_sip.c:6129 build_route: build_route: Retaining previous route: Jul 10 19:33:09 DEBUG[1925]: rtp.c:1378 ast_rtp_write: Ooh, format changed from unknown to ulaw Jul 10 19:33:12 DEBUG[1915]: chan_sip.c:3192 sip_alloc: Allocating new SIP dialog for E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 - REGISTER (No RTP) Jul 10 19:33:12 DEBUG[1915]: chan_sip.c:11186 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Jul 10 19:33:12 DEBUG[1915]: chan_sip.c:6640 register_verify: SIP REGISTER attempt failed for (null) : Bad digest user Jul 10 19:33:13 NOTICE[1915]: chan_sip.c:11092 handle_request_register: Registration from 'x-lite-john-pc ' failed for '10.1.1.160' - Username/auth name mismatch Jul 10 19:33:20 DEBUG[1925]: rtp.c:415 ast_rtcp_read: Got RTCP report of 96 bytes Jul 10 19:33:28 DEBUG[1915]: chan_sip.c:1323 __sip_autodestruct: Auto destroying call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' Jul 10 19:33:33 DEBUG[1925]: rtp.c:415 ast_rtcp_read: Got RTCP report of 96 bytes --- close_rtp_connection --- find_call +++ find_call +++ close_rtp_connection --- onCallCleared ooh323c_1 --- find_call DEBUG[1925]: rtp.c:1756 ast_rtp_bridge: Oooh, 'OOH323/ken_op-a00e' changed end address to 0.0.0.0:0 (format 0) +++ find_call Jul 10 19:33:38 DEBUG[1925]: rtp.c:1758 ast_rtp_bridge: Oooh, 'OOH323/ken_op-a00e' was 10.1.1.155:1720/(format 0) Jul 10 19:33:38 DEBUG[1925]: chan_sip.c:12971 sip_set_rtp_peer: Sending reinvite on SIP '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' - It's audio soon redirected to IP 10.3.3.239 Jul 10 19:33:38 DEBUG[1925]: rtp.c:1804 ast_rtp_bridge: Oooh, got a hangup Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:1379 __sip_ack: Acked pending invite 105 Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 105: Match Found Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:9631 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239 Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:6129 build_route: build_route: Retaining previous route: Jul 10 19:33:38 DEBUG[1925]: chan_sip.c:12971 sip_set_rtp_peer: Sending reinvite on SIP '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' - It's audio soon redirected to IP 10.3.3.239 Jul 10 19:33:38 DEBUG[1925]: channel.c:3505 ast_channel_bridge: Returning from native bridge, channels: OOH323/ken_op-a00e, SIP/6111-cbe1 Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:1379 __sip_ack: Acked pending invite 106 Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 106: Match Found Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:9631 handle_response_invite: SIP response 200 to RE-invite on outgoing call 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239 Jul 10 19:33:38 DEBUG[1915]: chan_sip.c:6129 build_route: build_route: Retaining previous route: Jul 10 19:33:38 DEBUG[1925]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/6111-cbe1' Jul 10 19:33:38 DEBUG[1925]: chan_sip.c:2418 sip_hangup: Hangup call SIP/6111-cbe1, SIP callid 1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239) Jul 10 19:33:39 DEBUG[1925]: chan_sip.c:2426 sip_hangup: update_call_counter(6111) - decrement call limit counter Jul 10 19:33:39 DEBUG[1925]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call Jul 10 19:33:39 DEBUG[1903]: chan_sip.c:11717 sip_devicestate: Checking device state for peer 6111 Jul 10 19:33:39 DEBUG[1915]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '1dc6d8e74a245bdc75ab71a0526bf5a8@10.3.3.239' of Request 107: Match Found Jul 10 19:33:39 DEBUG[1903]: devicestate.c:187 do_state_change: Changing state for SIP/6111 - state 1 (Not in use) Jul 10 19:33:39 DEBUG[1933]: app_queue.c:523 changethread: Device 'SIP/6111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Jul 10 19:33:39 DEBUG[1925]: app_dial.c:1619 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Jul 10 19:33:39 DEBUG[1903]: chan_sip.c:11717 sip_devicestate: Checking device state for peer 6111 Jul 10 19:33:39 DEBUG[1925]: app_macro.c:231 macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'OOH323/ken_op-a00e' in macro 'dial' Jul 10 19:33:39 DEBUG[1925]: app_macro.c:231 macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'OOH323/ken_op-a00e' in macro 'exten-vm' Jul 10 19:33:39 DEBUG[1925]: pbx.c:2316 __ast_pbx_run: Spawn extension (macro-dial,s,10) exited non-zero on 'OOH323/ken_op-a00e' Jul 10 19:33:39 DEBUG[1925]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. Jul 10 19:33:39 DEBUG[1925]: cdr_addon_mysql.c:222 mysql_log: 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-10 19:32:50','ken_op','','6111','default', 'OOH323/ken_op-a00e','SIP/6111-cbe1','Dial','SIP/6111||',49,32,'ANSWERED',3,'ast_h323','1152559970.0') Jul 10 19:33:39 ERROR[1925]: cdr_addon_mysql.c:226 mysql_log: mysql_cdr: Failed to insert into database: (1146) Table 'asterisk.cdr' doesn't existJul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ken_op' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6111' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'default' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'OOH323/ken_op-a00e' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6111-cbe1' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6111||' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-07-10 19:32:50' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-07-10 19:33:07' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-07-10 19:33:39' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '49' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '32' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ast_h323' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1152559970.0' Jul 10 19:33:39 DEBUG[1925]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jul 10 19:33:39 DEBUG[1925]: channel.c:1323 ast_hangup: Hanging up channel 'OOH323/ken_op-a00e' --- ooh323_hangup hanging ken_op +++ ooh323_hangup Jul 10 19:33:39 DEBUG[1903]: devicestate.c:187 do_state_change: Changing state for OOH323/ken_op - state 0 (Unknown) Jul 10 19:33:39 DEBUG[1934]: app_queue.c:523 changethread: Device 'OOH323/ken_op' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. --- ooh323_destroy Destroying ken_op +++ ooh323_destroy *CLI> *CLI> *CLI> *CLI> *CLI> stop now Beginning asterisk shutdown.... Executing last minute cleanups == Destroying musiconhold processes Asterisk cleanly ending (0). bash-2.05#