MJLM-Hou-AsteriVOX-00*CLI> MJLM-Hou-AsteriVOX-00*CLI> MJLM-Hou-AsteriVOX-00*CLI> MJLM-Hou-AsteriVOX-00*CLI> MJLM-Hou-AsteriVOX-00*CLI> core set debug 10 Core debug was 0 and is now 10 [Apr 7 16:42:23] DEBUG[25483]: acl.c:490 ast_ouraddrfor: Found IP address for this socket == Using SIP RTP CoS mark 5 [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:4215 do_setnat: Setting NAT on RTP to Off [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:6348 sip_alloc: Allocating new SIP dialog for 1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11 - INVITE (With RTP) [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:19634 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:4215 do_setnat: Setting NAT on RTP to Off [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:7556 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:18120 handle_request_invite: Checking SIP call limits for device [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:4813 update_call_counter: Updating call counter for incoming call [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:5773 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:5774 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:5775 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:5776 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:5806 sip_new: This channel will not be able to handle video. [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:10852 build_route: build_route: Contact hop: [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:18193 handle_request_invite: Incoming INVITE with 'timer' option enabled [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:20577 parse_minse: Received Min-SE: 1800 [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:20486 start_session_timer: Session timer started: 294 - 1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11 [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:18333 handle_request_invite: SIP/192.168.200.11-b7a71198: New call is still down.... Trying... [Apr 7 16:42:23] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:42:23] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - 192.168.200.11 [Apr 7 16:42:23] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer 192.168.200.11 [Apr 7 16:42:23] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/192.168.200.11 - state 2 (In use) [Apr 7 16:42:23] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/192.168.200.11' state '2' [Apr 7 16:42:23] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/192.168.200.11' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3008 pbx_substitute_variables_helper_full: Function result is '2819002620' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3075 pbx_substitute_variables_helper_full: Expression result is '0' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'ExecIf' -- Executing [1688@incoming:1] ExecIf("SIP/192.168.200.11-b7a71198", "0?HangUp()") in new stack [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'Goto' -- Executing [1688@incoming:2] Goto("SIP/192.168.200.11-b7a71198", "did,1688,1") in new stack -- Goto (did,1688,1) [Apr 7 16:42:23] NOTICE[25509]: /home/murf/asterisk/1.6.1/main/ast_expr2.y:760 compose_func_args: argbuf allocated 5 bytes; [Apr 7 16:42:23] NOTICE[25509]: /home/murf/asterisk/1.6.1/main/ast_expr2.y:779 compose_func_args: argbuf uses 4 bytes; [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3075 pbx_substitute_variables_helper_full: Expression result is '0' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3008 pbx_substitute_variables_helper_full: Function result is '' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3008 pbx_substitute_variables_helper_full: Function result is 'Unavailable' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'Set' -- Executing [1688@did:1] Set("SIP/192.168.200.11-b7a71198", "CALLERID(name)=Unavailable") in new stack [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3008 pbx_substitute_variables_helper_full: Function result is 'Unavailable' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3008 pbx_substitute_variables_helper_full: Function result is '2819002620' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'NoOp' -- Executing [1688@did:2] NoOp("SIP/192.168.200.11-b7a71198", "Unavailable is calling 1688 from 2819002620") in new stack [Apr 7 16:42:23] DEBUG[25509]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:23] DEBUG[25509]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3008 pbx_substitute_variables_helper_full: Function result is 'NOT_INUSE' [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'NoOp' -- Executing [1688@did:3] NoOp("SIP/192.168.200.11-b7a71198", "1688 is currently NOT_INUSE") in new stack [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'Ringing' -- Executing [1688@did:4] Ringing("SIP/192.168.200.11-b7a71198", "") in new stack [Apr 7 16:42:23] DEBUG[25509]: chan_sip.c:2870 __sip_xmit: Trying to put 'SIP/2.0 18' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:42:23] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'Wait' -- Executing [1688@did:5] Wait("SIP/192.168.200.11-b7a71198", "3") in new stack [Apr 7 16:42:26] DEBUG[25509]: pbx.c:3075 pbx_substitute_variables_helper_full: Expression result is '1' [Apr 7 16:42:26] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'GotoIf' -- Executing [1688@did:6] GotoIf("SIP/192.168.200.11-b7a71198", "1?30:") in new stack -- Goto (did,1688,30) [Apr 7 16:42:26] DEBUG[25509]: pbx.c:3174 pbx_extension_helper: Launching 'Dial' -- Executing [1688@did:30] Dial("SIP/192.168.200.11-b7a71198", "SIP/sip1688&SIP/688,17") in new stack [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:21006 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) == Using SIP RTP CoS mark 5 [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:6348 sip_alloc: Allocating new SIP dialog for 1c8b8691244d1df97c58e4f550338761@127.0.1.1 - INVITE (With RTP) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:4215 do_setnat: Setting NAT on RTP to Off [Apr 7 16:42:26] DEBUG[25509]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:5773 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:5774 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:5775 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:5776 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:5778 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:5806 sip_new: This channel will not be able to handle video. [Apr 7 16:42:26] DEBUG[25509]: dsp.c:468 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Apr 7 16:42:26] DEBUG[25509]: dsp.c:468 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Apr 7 16:42:26] DEBUG[25509]: rtp.c:2178 ast_rtp_make_compatible: Seeded SDP of 'SIP/sip1688-b7a84510' with that of 'SIP/192.168.200.11-b7a71198' [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 7 16:42:26] DEBUG[25509]: channel.c:3985 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:4616 sip_call: Outgoing Call for sip1688 [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:4813 update_call_counter: Updating call counter for outgoing call [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:4638 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 7 16:42:26] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:26] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:26] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 6 (Ringing) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:8679 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False Text flag: False [Apr 7 16:42:26] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '6' [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:8680 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:8828 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:42:26] DEBUG[25509]: channel.c:2931 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=31) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:8947 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Apr 7 16:42:26] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:2634 initialize_initreq: Initializing initreq for method INVITE - callid 4501b44c25dca5c3308e3f987501a9c7@192.168.100.180 [Apr 7 16:42:26] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:26] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:2870 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.101.250:5060 -- Called sip1688 [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:21006 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) == Using SIP RTP CoS mark 5 [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:6348 sip_alloc: Allocating new SIP dialog for 178ded475fb41bf93fddbbd425cdc8d7@127.0.1.1 - INVITE (With RTP) [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:21087 sip_request_call: Cant create SIP call - target device not registered [Apr 7 16:42:26] DEBUG[25509]: chan_sip.c:4960 sip_destroy: Destroying SIP dialog 178ded475fb41bf93fddbbd425cdc8d7@127.0.1.1 [Apr 7 16:42:26] WARNING[25509]: app_dial.c:1518 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Unknown) [Apr 7 16:42:26] DEBUG[25483]: chan_sip.c:3406 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4501b44c25dca5c3308e3f987501a9c7@192.168.100.180' Request 102: Found [Apr 7 16:42:26] DEBUG[25483]: chan_sip.c:15875 handle_response_invite: SIP response 100 to standard invite [Apr 7 16:42:27] DEBUG[25483]: chan_sip.c:3406 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4501b44c25dca5c3308e3f987501a9c7@192.168.100.180' Request 102: Found [Apr 7 16:42:27] DEBUG[25483]: chan_sip.c:15875 handle_response_invite: SIP response 180 to standard invite [Apr 7 16:42:27] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:27] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:27] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 6 (Ringing) -- SIP/sip1688-b7a84510 is ringing [Apr 7 16:42:27] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '6' [Apr 7 16:42:27] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 7 16:42:27] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:27] DEBUG[25509]: rtp.c:2105 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/192.168.200.11-b7a71198' with that of 'SIP/sip1688-b7a84510' [Apr 7 16:42:27] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:27] DEBUG[25509]: chan_sip.c:2870 __sip_xmit: Trying to put 'SIP/2.0 18' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:3329 __sip_ack: Acked pending invite 102 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:3366 __sip_ack: Stopping retransmission on '4501b44c25dca5c3308e3f987501a9c7@192.168.100.180' of Request 102: Match Found [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:15875 handle_response_invite: SIP response 200 to standard invite [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:7556 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:7561 process_sdp: We have an owner, now see if we need to change this call [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:4813 update_call_counter: Updating call counter for outgoing call [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:10852 build_route: build_route: Contact hop: [Apr 7 16:42:29] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 2 (In use) [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '2' [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'ACK sip:si' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:42:29] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 7 16:42:29] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:29] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 -- SIP/sip1688-b7a84510 answered SIP/192.168.200.11-b7a71198 [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:29] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 2 (In use) [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '2' [Apr 7 16:42:29] DEBUG[25509]: rtp.c:2105 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/192.168.200.11-b7a71198' with that of 'SIP/sip1688-b7a84510' [Apr 7 16:42:29] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 7 16:42:29] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:29] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:5345 sip_answer: SIP answering channel: SIP/192.168.200.11-b7a71198 [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - 192.168.200.11 [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:9011 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 7 16:42:29] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer 192.168.200.11 [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8679 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 7 16:42:29] DEBUG[25472]: channel.c:1180 channel_find_locked: Avoiding initial deadlock for channel '0xb7a74fe8' [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8680 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 7 16:42:29] DEBUG[25472]: channel.c:1180 channel_find_locked: Avoiding initial deadlock for channel '0xb7a74fe8' [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8828 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:42:29] DEBUG[25509]: channel.c:2931 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Apr 7 16:42:29] DEBUG[25472]: channel.c:1180 channel_find_locked: Avoiding initial deadlock for channel '0xb7a74fe8' [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8947 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 7 16:42:29] DEBUG[25472]: channel.c:1180 channel_find_locked: Avoiding initial deadlock for channel '0xb7a74fe8' [Apr 7 16:42:29] DEBUG[25472]: channel.c:1180 channel_find_locked: Avoiding initial deadlock for channel '0xb7a74fe8' [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:2870 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:42:29] DEBUG[25472]: channel.c:1180 channel_find_locked: Avoiding initial deadlock for channel '0xb7a74fe8' [Apr 7 16:42:29] DEBUG[25472]: channel.c:1180 channel_find_locked: Avoiding initial deadlock for channel '0xb7a74fe8' [Apr 7 16:42:29] DEBUG[25509]: features.c:2483 ast_bridge_call: bridge answer set, chan answer set [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/192.168.200.11 - state 2 (In use) [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/192.168.200.11' state '2' [Apr 7 16:42:29] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/192.168.200.11' changed to state '2' (In use) but we don't care because they're not a member of any queue. -- Native bridging SIP/192.168.200.11-b7a71198 and SIP/sip1688-b7a84510 [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:23042 sip_set_rtp_peer: Deferring reinvite on SIP '1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11' - It's audio will be redirected to IP 192.168.101.250 [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:23039 sip_set_rtp_peer: Sending reinvite on SIP '4501b44c25dca5c3308e3f987501a9c7@192.168.100.180' - It's audio soon redirected to IP 192.168.200.10 [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8679 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8680 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8828 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:42:29] DEBUG[25509]: channel.c:2931 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=31) [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:8947 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:2632 initialize_initreq: Initializing already initialized SIP dialog 4501b44c25dca5c3308e3f987501a9c7@192.168.100.180 (presumably reinvite) [Apr 7 16:42:29] DEBUG[25509]: chan_sip.c:2870 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:19634 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:3366 __sip_ack: Stopping retransmission on '1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11' of Response 101: Match Found [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:15836 check_pendings: Sending pending reinvite on '1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11' [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:8679 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:8680 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:8828 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:42:29] DEBUG[25483]: channel.c:2931 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:8947 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:2632 initialize_initreq: Initializing already initialized SIP dialog 1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11 (presumably reinvite) [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:3406 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11' Request 102: Found [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:15873 handle_response_invite: SIP response 100 to RE-invite on outgoing call 1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11 [Apr 7 16:42:29] DEBUG[25509]: rtp.c:3723 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 7 16:42:29] DEBUG[25509]: rtp.c:3739 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:3329 __sip_ack: Acked pending invite 103 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:3366 __sip_ack: Stopping retransmission on '4501b44c25dca5c3308e3f987501a9c7@192.168.100.180' of Request 103: Match Found [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:15873 handle_response_invite: SIP response 200 to RE-invite on outgoing call 4501b44c25dca5c3308e3f987501a9c7@192.168.100.180 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:7556 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:7561 process_sdp: We have an owner, now see if we need to change this call [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:4813 update_call_counter: Updating call counter for outgoing call [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:29] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:29] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'ACK sip:si' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 2 (In use) [Apr 7 16:42:29] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '2' [Apr 7 16:42:29] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 7 16:42:29] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:29] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:29] DEBUG[25509]: rtp.c:3723 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 7 16:42:29] DEBUG[25509]: rtp.c:3739 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 7 16:42:34] DEBUG[25483]: chan_sip.c:19634 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 7 16:42:34] DEBUG[25483]: chan_sip.c:6348 sip_alloc: Allocating new SIP dialog for 03f5781c461b4b29393e998458c0bab5@127.0.1.1 - OPTIONS (No RTP) [Apr 7 16:42:34] DEBUG[25483]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 7 16:42:34] DEBUG[25483]: chan_sip.c:2634 initialize_initreq: Initializing initreq for method OPTIONS - callid 520b04bf59c5f0a5160a56e35e4a44da@192.168.100.180 [Apr 7 16:42:34] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'OPTIONS si' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:42:34] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:42:34] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:34] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:34] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 2 (In use) [Apr 7 16:42:34] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '2' [Apr 7 16:42:34] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 7 16:42:34] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:34] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:34] DEBUG[25483]: chan_sip.c:3366 __sip_ack: Stopping retransmission on '520b04bf59c5f0a5160a56e35e4a44da@192.168.100.180' of Request 102: Match Found [Apr 7 16:42:34] DEBUG[25483]: chan_sip.c:4960 sip_destroy: Destroying SIP dialog 520b04bf59c5f0a5160a56e35e4a44da@192.168.100.180 [Apr 7 16:42:38] DEBUG[25483]: chan_sip.c:19634 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Apr 7 16:42:38] DEBUG[25483]: chan_sip.c:2645 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4501b44c25dca5c3308e3f987501a9c7@192.168.100.180 [Apr 7 16:42:38] DEBUG[25483]: chan_sip.c:19135 handle_request_bye: Received bye, issuing owner hangup [Apr 7 16:42:38] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:42:38] DEBUG[25509]: rtp.c:3932 bridge_native_loop: Oooh, got a hangup [Apr 7 16:42:38] DEBUG[25509]: chan_sip.c:23042 sip_set_rtp_peer: Deferring reinvite on SIP '1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11' - It's audio will be redirected to IP 192.168.100.180 [Apr 7 16:42:38] DEBUG[25509]: channel.c:4843 ast_channel_bridge: Returning from native bridge, channels: SIP/192.168.200.11-b7a71198, SIP/sip1688-b7a84510 [Apr 7 16:42:38] DEBUG[25509]: channel.c:1644 ast_hangup: Hanging up channel 'SIP/sip1688-b7a84510' [Apr 7 16:42:38] DEBUG[25509]: chan_sip.c:5174 sip_hangup: Hangup call SIP/sip1688-b7a84510, SIP callid 4501b44c25dca5c3308e3f987501a9c7@192.168.100.180 [Apr 7 16:42:38] DEBUG[25509]: chan_sip.c:4813 update_call_counter: Updating call counter for outgoing call [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:38] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 1 (Not in use) [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '1' [Apr 7 16:42:38] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:38] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:38] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:38] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/sip1688 - state 1 (Not in use) [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/sip1688' state '1' [Apr 7 16:42:38] DEBUG[25473]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:42:38] DEBUG[25509]: rtp.c:2055 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 7 16:42:38] DEBUG[25473]: chan_sip.c:20912 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:42:38] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/sip1688' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 7 16:42:38] DEBUG[25509]: app_dial.c:2024 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 7 16:42:38] DEBUG[25509]: pbx.c:3774 __ast_pbx_run: Spawn extension (did,1688,30) exited non-zero on 'SIP/192.168.200.11-b7a71198' == Spawn extension (did, 1688, 30) exited non-zero on 'SIP/192.168.200.11-b7a71198' [Apr 7 16:42:38] DEBUG[25509]: channel.c:1549 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/192.168.200.11-b7a71198' [Apr 7 16:42:38] DEBUG[25509]: channel.c:1644 ast_hangup: Hanging up channel 'SIP/192.168.200.11-b7a71198' [Apr 7 16:42:38] DEBUG[25509]: chan_sip.c:5174 sip_hangup: Hangup call SIP/192.168.200.11-b7a71198, SIP callid 1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11 [Apr 7 16:42:38] DEBUG[25509]: chan_sip.c:20467 stop_session_timer: Session timer stopped: -1 - 1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11 [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:366 _ast_device_state: No provider found, checking channel drivers for SIP - 192.168.200.11 [Apr 7 16:42:38] DEBUG[25472]: chan_sip.c:20912 sip_devicestate: Checking device state for peer 192.168.200.11 [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:487 do_state_change: Changing state for SIP/192.168.200.11 - state 1 (Not in use) [Apr 7 16:42:38] DEBUG[25472]: devicestate.c:467 devstate_event: device 'SIP/192.168.200.11' state '1' [Apr 7 16:42:38] DEBUG[25475]: app_queue.c:787 handle_statechange: Device 'SIP/192.168.200.11' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 7 16:42:39] DEBUG[25483]: chan_sip.c:4960 sip_destroy: Destroying SIP dialog 4501b44c25dca5c3308e3f987501a9c7@192.168.100.180 [Apr 7 16:42:42] DEBUG[25483]: chan_sip.c:19634 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Apr 7 16:42:42] DEBUG[25483]: chan_sip.c:3329 __sip_ack: Acked pending invite 102 [Apr 7 16:42:42] DEBUG[25483]: chan_sip.c:3366 __sip_ack: Stopping retransmission on '1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11' of Request 102: Match Found [Apr 7 16:42:42] DEBUG[25483]: chan_sip.c:2645 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1fabf800-1df141c9-6834-bc8a8c0@192.168.200.11 [Apr 7 16:42:42] DEBUG[25483]: chan_sip.c:19138 handle_request_bye: Received bye, no owner, selfdestruct soon. [Apr 7 16:42:42] DEBUG[25483]: chan_sip.c:2870 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.200.11:5060 MJLM-Hou-AsteriVOX-00*CLI> core set debug 0 Core debug is now OFF*CLI> MJLM-Hou-AsteriVOX-00*CLI>