server-voip:/usr/src/voip/asterisk-trunk # asterisk -r Asterisk SVN-trunk-r100325, Copyright (C) 1999 - 2008 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= NOTE: This is a development version of Asterisk, and should not be used in production installations. Connected to Asterisk SVN-trunk-r100325 currently running on server-voip (pid = 3540) Verbosity is at least 5 Core debug is at least 9 -- Remote UNIX connection [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5721 find_call: = No match Their Call ID: 7aa20d424cb832423b91649c2f882fa1@127.0.0.2 Their Tag 1C20D1C5 Our tag: as67043068 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5721 find_call: = No match Their Call ID: 3642a72429afbd4f3a6f77c1061c2590@127.0.0.2 Their Tag 391D19C5 Our tag: as0b94281d [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5721 find_call: = No match Their Call ID: 4ff71f39653d573715c910930e2fe4fe@127.0.0.2 Their Tag Our tag: as7d0e3b44 [Jan 25 13:24:41] DEBUG[22124]: acl.c:482 ast_ouraddrfor: Found IP address for this socket == Using SIP RTP TOS bits 40 == Using SIP RTP CoS mark 6 == Using SIP VRTP TOS bits 136 == Using SIP VRTP CoS mark 5 == Using UDPTL TOS bits 40 == Using UDPTL CoS mark 6 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3755 do_setnat: Setting NAT on RTP to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3759 do_setnat: Setting NAT on VRTP to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3763 do_setnat: Setting NAT on UDPTL to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5656 sip_alloc: Allocating new SIP dialog for 7490d387-85f871b2@192.168.32.89 - INVITE (With RTP) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:17633 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3755 do_setnat: Setting NAT on RTP to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3759 do_setnat: Setting NAT on VRTP to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3763 do_setnat: Setting NAT on UDPTL to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:2499 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket... [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5721 find_call: = Found Their Call ID: 7490d387-85f871b2@192.168.32.89 Their Tag d157f1834fd8be6o0 Our tag: as0107dd6e [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:17633 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:2954 __sip_ack: Stopping retransmission on '7490d387-85f871b2@192.168.32.89' of Response 101: Match Found [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5721 find_call: = Found Their Call ID: 7490d387-85f871b2@192.168.32.89 Their Tag d157f1834fd8be6o0 Our tag: as0107dd6e [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:17633 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3755 do_setnat: Setting NAT on RTP to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3759 do_setnat: Setting NAT on VRTP to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:3763 do_setnat: Setting NAT on UDPTL to Off [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:6623 process_sdp: T38 state changed to 0 on channel [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:6711 process_sdp: We're settling with these formats: 0x108 (alaw|g729) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:16135 handle_request_invite: Checking SIP call limits for device 105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:4255 update_call_counter: Updating call counter for incoming call [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5086 sip_new: *** Our native formats are 0x8 (alaw) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5087 sip_new: *** Joint capabilities are 0x108 (alaw|g729) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5088 sip_new: *** Our capabilities are 0x108 (alaw|g729) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5089 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5117 sip_new: This channel will not be able to handle video. [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:9738 build_route: build_route: Contact hop: "SPA962" [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:16345 handle_request_invite: SIP/105-08332cb0: New call is still down.... Trying... [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:2499 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket... [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105 - state 3 (Busy) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105' changed to state '3' (Busy) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip_regs WHERE name = '105-08332cb0' [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip WHERE name = '105-08332cb0' AND host = 'dynamic' [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip WHERE name = '105-08332cb0' [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105-08332cb0 - state 1 (Not in use) [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105-08332cb0' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105 - state 3 (Busy) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105' changed to state '3' (Busy) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: pbx.c:2652 pbx_extension_helper: Launching 'Dial' -- Executing [52@default:1] Dial("SIP/105-08332cb0", "Local/01@ext-dialer-message/n") in new stack [Jan 25 13:24:41] DEBUG[22124]: rtp.c:1907 ast_rtp_make_compatible: Channel 'Local/01@ext-dialer-message-c647;1' has no RTP, not doing anything [Jan 25 13:24:41] DEBUG[22124]: channel.c:3500 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jan 25 13:24:41] DEBUG[22124]: channel.c:3500 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jan 25 13:24:41] DEBUG[22124]: channel.c:3500 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 01@ext-dialer-message/n [Jan 25 13:24:41] DEBUG[22124]: pbx.c:2652 pbx_extension_helper: Launching 'Set' -- Executing [01@ext-dialer-message:1] Set("Local/01@ext-dialer-message-c647;2", "AGISIGHUP=yes") in new stack [Jan 25 13:24:41] DEBUG[22124]: pbx.c:2652 pbx_extension_helper: Launching 'NoCDR' -- Executing [01@ext-dialer-message:2] NoCDR("Local/01@ext-dialer-message-c647;2", "") in new stack [Jan 25 13:24:41] DEBUG[22124]: pbx.c:2652 pbx_extension_helper: Launching 'AGI' -- Executing [01@ext-dialer-message:3] AGI("Local/01@ext-dialer-message-c647;2", "caller/dial-message.php,1") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/caller/dial-message.php -- AGI Script Executing Application: (Wait) Options: (0.3) -- AGI Script Executing Application: (Set) Options: (CHANNEL(language)=ru-1) -- AGI Script Executing Application: (Playback) Options: (main_1_1) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message-c647;2 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message-c647;1 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message -- Local/01@ext-dialer-message-c647;1 answered SIP/105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:4726 sip_answer: SIP answering channel: SIP/105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:8096 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:7829 add_sdp: ** Our capability: 0x108 (alaw|g729) Video flag: True Text flag: True [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:7830 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:7979 add_sdp: -- Done with adding codecs to SDP [Jan 25 13:24:41] DEBUG[22124]: channel.c:2528 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=37) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:8039 add_sdp: Done building SDP. Settling with this capability: 0x108 (alaw|g729) [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:2499 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket... [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message-c647;2 [Jan 25 13:24:41] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message-c647;2 exists (devicestate) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message-c647;2 - state 4 (Invalid) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message [Jan 25 13:24:41] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message exists (devicestate) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message - state 2 (In use) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message-c647;1 [Jan 25 13:24:41] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message-c647;1 exists (devicestate) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message-c647;1 - state 4 (Invalid) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message [Jan 25 13:24:41] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message exists (devicestate) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message - state 2 (In use) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105-08332cb0 [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message-c647;2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message-c647;1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip_regs WHERE name = '105-08332cb0' [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip WHERE name = '105-08332cb0' AND host = 'dynamic' [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:41] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip WHERE name = '105-08332cb0' [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105-08332cb0 - state 1 (Not in use) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105 - state 3 (Busy) [Jan 25 13:24:41] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105-08332cb0' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105' changed to state '3' (Busy) but we don't care because they're not a member of any queue. [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:5721 find_call: = Found Their Call ID: 7490d387-85f871b2@192.168.32.89 Their Tag d157f1834fd8be6o0 Our tag: as2b567ae9 [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:17633 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Jan 25 13:24:41] DEBUG[22124]: chan_sip.c:2954 __sip_ack: Stopping retransmission on '7490d387-85f871b2@192.168.32.89' of Response 102: Match Found [Jan 25 13:24:42] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:42] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'main_1_1.slin' (language 'ru-1') [Jan 25 13:24:42] DEBUG[22124]: rtp.c:3165 ast_rtp_write: Ooh, format changed from unknown to alaw [Jan 25 13:24:42] DEBUG[22124]: rtp.c:3181 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:5721 find_call: = Found Their Call ID: 7490d387-85f871b2@192.168.32.89 Their Tag d157f1834fd8be6o0 Our tag: as2b567ae9 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:17633 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:2302 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7490d387-85f871b2@192.168.32.89 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:17172 handle_request_bye: Received bye, issuing owner hangup [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:2499 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket... [Jan 25 13:24:44] DEBUG[22124]: channel.c:3976 ast_generic_bridge: Didn't get a frame from channel: SIP/105-08332cb0 [Jan 25 13:24:44] DEBUG[22124]: channel.c:4316 ast_channel_bridge: Bridge stops bridging channels SIP/105-08332cb0 and Local/01@ext-dialer-message-c647;1 [Jan 25 13:24:44] DEBUG[22124]: channel.c:1477 ast_hangup: Hanging up channel 'Local/01@ext-dialer-message-c647;1' [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message-c647;1 [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message [Jan 25 13:24:44] DEBUG[22124]: rtp.c:1832 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jan 25 13:24:44] DEBUG[22124]: app_dial.c:1891 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jan 25 13:24:44] DEBUG[22124]: pbx.c:3292 __ast_pbx_run: Spawn extension (default,52,1) exited non-zero on 'SIP/105-08332cb0' == Spawn extension (default, 52, 1) exited non-zero on 'SIP/105-08332cb0' [Jan 25 13:24:44] DEBUG[22124]: channel.c:1378 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/105-08332cb0' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2652 pbx_extension_helper: Launching 'Hangup' -- Executing [h@default:1] Hangup("SIP/105-08332cb0", "") in new stack [Jan 25 13:24:44] DEBUG[22124]: pbx.c:3420 __ast_pbx_run: Spawn extension (default,h,1) exited non-zero on 'SIP/105-08332cb0' == Spawn extension (default, h, 1) exited non-zero on 'SIP/105-08332cb0' [Jan 25 13:24:44] DEBUG[22124]: channel.c:1477 ast_hangup: Hanging up channel 'SIP/105-08332cb0' [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:4563 sip_hangup: Hangup call SIP/105-08332cb0, SIP callid 7490d387-85f871b2@192.168.32.89 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:4255 update_call_counter: Updating call counter for incoming call [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105 [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105-08332cb0 [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/105 [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '"SPA962" <105>' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '105' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '52' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is 'default' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is 'SIP/105-08332cb0' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is 'Local/01@ext-dialer-message-c647;1' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is 'Dial' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is 'Local/01@ext-dialer-message/n' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '2008-01-25 13:24:41' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '2008-01-25 13:24:41' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '2008-01-25 13:24:44' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '3' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '3' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '1201245881.9' [Jan 25 13:24:44] DEBUG[22124]: pbx.c:2489 pbx_substitute_variables_helper_full: Function result is '' [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message-c647;1 [Jan 25 13:24:44] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message-c647;1 exists (devicestate) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message-c647;1 - state 4 (Invalid) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message [Jan 25 13:24:44] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message exists (devicestate) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message - state 1 (Not in use) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105 - state 1 (Not in use) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105-08332cb0 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105-08332cb0 [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:44] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message-c647;1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 25 13:24:44] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 25 13:24:44] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'calldate' of type 'datetime' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'clid' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'src' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'dst' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'dcontext' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'channel' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'dstchannel' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'lastapp' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'lastdata' of type 'varchar(80)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'duration' of type 'int(11)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'billsec' of type 'int(11)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'disposition' of type 'varchar(45)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'amaflags' of type 'int(11)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'accountcode' of type 'varchar(20)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:241 mysql_log: Got a field 'userfield' of type 'varchar(255)' [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:309 mysql_log: Inserting a CDR record. [Jan 25 13:24:44] DEBUG[22124]: cdr_addon_mysql.c:319 mysql_log: SQL command as follows: INSERT INTO ast_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('','"SPA962" <105>','105','52','default','SIP/105-08332cb0','Local/01@ext-dialer-message-c647;1','Dial','Local/01@ext-dialer-message/n','3','3','ANSWERED','3','','') [Jan 25 13:24:44] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:44] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip_regs WHERE name = '105-08332cb0' [Jan 25 13:24:44] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:44] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip WHERE name = '105-08332cb0' AND host = 'dynamic' [Jan 25 13:24:44] DEBUG[22124]: res_config_mysql.c:866 mysql_reconnect: MySQL RealTime: Connection okay. [Jan 25 13:24:44] DEBUG[22124]: res_config_mysql.c:149 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM ast_rt_sip WHERE name = '105-08332cb0' [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105-08332cb0 - state 1 (Not in use) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for SIP/105 - state 1 (Not in use) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - 105 [Jan 25 13:24:44] DEBUG[22124]: chan_sip.c:18684 sip_devicestate: Checking device state for peer 105 [Jan 25 13:24:44] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105-08332cb0' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 25 13:24:44] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'SIP/105' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- AGI Script Executing Application: (Playback) Options: (pjatnadzatoe) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'pjatnadzatoe.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for pjatnadzatoe -- AGI Script Executing Application: (Playback) Options: (mon-0) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'mon-0.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for mon-0 -- AGI Script Executing Application: (Playback) Options: (main_1_3) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'main_1_3.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for main_1_3 [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:145 do_say: string depth <0> [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:157 do_say: try in [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:183 do_say: value is <1234> [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:198 do_say: doing [digits/1f] [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'digits/1f.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:123 s_streamwait3: Unable to play message digits/1f -- AGI Script Executing Application: (Playback) Options: (rubley) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'rubley.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for rubley [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:145 do_say: string depth <0> [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:157 do_say: try in [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:183 do_say: value is <87> [Jan 25 13:24:44] DEBUG[22124]: app_playback.c:198 do_say: doing [digits/80] [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'digits/80.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:123 s_streamwait3: Unable to play message digits/80 -- AGI Script Executing Application: (Playback) Options: (kopejek) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'kopejek.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for kopejek -- AGI Script Executing Application: (Playback) Options: (main_1_8) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'main_1_8.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for main_1_8 -- AGI Script Executing Application: (Playback) Options: (main_1_9) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing 'main_1_9.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for main_1_9 -- AGI Script Executing Application: (Playback) Options: (747374) [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format alaw [Jan 25 13:24:44] DEBUG[22124]: channel.c:2995 set_format: Set channel Local/01@ext-dialer-message-c647;2 to write format slin [Jan 25 13:24:44] WARNING[22124]: file.c:623 ast_readaudio_callback: Failed to write frame [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals -- Playing '747374.slin' (language 'ru-1') [Jan 25 13:24:44] WARNING[22124]: app_playback.c:445 playback_exec: ast_streamfile failed on Local/01@ext-dialer-message-c647;2 for 747374 -- AGI Script caller/dial-message.php completed, returning -1 [Jan 25 13:24:44] DEBUG[22124]: pbx.c:3274 __ast_pbx_run: Extension 01, priority 3 returned normally even though call was hung up [Jan 25 13:24:44] DEBUG[22124]: channel.c:1378 ast_softhangup_nolock: Soft-Hanging up channel 'Local/01@ext-dialer-message-c647;2' [Jan 25 13:24:44] DEBUG[22124]: channel.c:2004 ast_settimeout: Scheduling timer at 0 sample intervals [Jan 25 13:24:44] DEBUG[22124]: channel.c:1477 ast_hangup: Hanging up channel 'Local/01@ext-dialer-message-c647;2' [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message-c647;2 [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/01@ext-dialer-message [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message-c647;2 [Jan 25 13:24:44] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message-c647;2 exists (devicestate) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message-c647;2 - state 4 (Invalid) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - 01@ext-dialer-message [Jan 25 13:24:44] DEBUG[22124]: chan_local.c:141 local_devicestate: Checking if extension 01@ext-dialer-message exists (devicestate) [Jan 25 13:24:44] DEBUG[22124]: devicestate.c:430 do_state_change: Changing state for Local/01@ext-dialer-message - state 1 (Not in use) [Jan 25 13:24:44] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message-c647;2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jan 25 13:24:44] DEBUG[22124]: app_queue.c:689 handle_statechange: Device 'Local/01@ext-dialer-message' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13268 sip_dump_history: ---------- SIP HISTORY for '7490d387-85f871b2@192.168.32.89' [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13272 sip_dump_history: * SIP Call [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 001. Rx INVITE / 101 INVITE / sip:52@192.168.32.1 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 002. AuthChal Auth challenge sent for - nc 0 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 003. TxRespRel SIP/2.0 / 101 INVITE - 401 Unauthorized [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 004. SchedDestroy 32000 ms [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 005. Rx ACK / 101 ACK / sip:52@192.168.32.1 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 006. Rx INVITE / 102 INVITE / sip:52@192.168.32.1 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 007. CancelDestroy [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 008. Invite New call: 7490d387-85f871b2@192.168.32.89 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 009. AuthOK Auth challenge succesful for 105 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 010. NewChan Channel SIP/105-08332cb0 - from 7490d387-85f871b2@192.168.32.89 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 011. TxResp SIP/2.0 / 102 INVITE - 100 Trying [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 012. TxRespRel SIP/2.0 / 102 INVITE - 200 OK [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 013. Rx ACK / 102 ACK / sip:52@192.168.32.1 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 014. Rx BYE / 103 BYE / sip:52@192.168.32.1 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 015. RTCPaudio Quality:ssrc=1503990642;themssrc=2456583391;lp=0;rxjitter=0.000 [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 016. TxResp SIP/2.0 / 103 BYE - 200 OK [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13275 sip_dump_history: 017. Hangup Cause Normal Clearing [Jan 25 13:24:45] DEBUG[22124]: chan_sip.c:13278 sip_dump_history: ---------- END SIP HISTORY for '7490d387-85f871b2@192.168.32.89' server-voip*CLI> exit