MJLM-Hou-AsteriVOX-00*CLI> MJLM-Hou-AsteriVOX-00*CLI> MJLM-Hou-AsteriVOX-00*CLI> [Apr 7 16:24:39] DEBUG[23195]: acl.c:490 ast_ouraddrfor: Found IP address for this socket == Using SIP RTP CoS mark 5 [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:4187 do_setnat: Setting NAT on RTP to Off [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:6286 sip_alloc: Allocating new SIP dialog for a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 - INVITE (With RTP) [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:19477 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:4187 do_setnat: Setting NAT on RTP to Off [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:7504 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:17905 handle_request_invite: Checking SIP call limits for device [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:4773 update_call_counter: Updating call counter for incoming call [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:5706 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:5707 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:5708 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:5709 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:5739 sip_new: This channel will not be able to handle video. [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:10761 build_route: build_route: Contact hop: [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:17978 handle_request_invite: Incoming INVITE with 'timer' option enabled [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:20418 parse_minse: Received Min-SE: 1800 [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:20327 start_session_timer: Session timer started: 435 - a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:18118 handle_request_invite: SIP/192.168.200.11-b3506dc0: New call is still down.... Trying... [Apr 7 16:24:39] DEBUG[23195]: chan_sip.c:2863 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:39] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - 192.168.200.11 [Apr 7 16:24:39] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer 192.168.200.11 [Apr 7 16:24:39] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/192.168.200.11 - state 2 (In use) [Apr 7 16:24:39] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/192.168.200.11' state '2' [Apr 7 16:24:39] DEBUG[23187]: 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:24:39] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/192.168.200.11' [Apr 7 16:24:39] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'In use' for 'SIP/192.168.200.11' [Apr 7 16:24:39] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 2 [Apr 7 16:24:39] DEBUG[23183]: devicestate.c:654 process_collection: Aggregate state for device 'SIP/192.168.200.11' has changed to 'In use' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:2990 pbx_substitute_variables_helper_full: Function result is '2819002620' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3057 pbx_substitute_variables_helper_full: Expression result is '0' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'ExecIf' -- Executing [1688@incoming:1] ExecIf("SIP/192.168.200.11-b3506dc0", "0?HangUp()") in new stack [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'Goto' -- Executing [1688@incoming:2] Goto("SIP/192.168.200.11-b3506dc0", "did,1688,1") in new stack -- Goto (did,1688,1)I> [Apr 7 16:24:39] NOTICE[24448]: ast_expr2.y:703 compose_func_args: argbuf allocated 5 bytes; [Apr 7 16:24:39] NOTICE[24448]: ast_expr2.y:722 compose_func_args: argbuf uses 4 bytes; [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3057 pbx_substitute_variables_helper_full: Expression result is '0' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:2990 pbx_substitute_variables_helper_full: Function result is '' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:2990 pbx_substitute_variables_helper_full: Function result is 'Unavailable' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'Set' -- Executing [1688@did:1] Set("SIP/192.168.200.11-b3506dc0", "CALLERID(name)=Unavailable") in new stack [Apr 7 16:24:39] DEBUG[24448]: pbx.c:2990 pbx_substitute_variables_helper_full: Function result is 'Unavailable' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:2990 pbx_substitute_variables_helper_full: Function result is '2819002620' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'NoOp' -- Executing [1688@did:2] NoOp("SIP/192.168.200.11-b3506dc0", "Unavailable is calling 1688 from 2819002620") in new stack [Apr 7 16:24:39] DEBUG[24448]: pbx.c:2990 pbx_substitute_variables_helper_full: Function result is 'NOT_INUSE' [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'NoOp' -- Executing [1688@did:3] NoOp("SIP/192.168.200.11-b3506dc0", "1688 is currently NOT_INUSE") in new stack [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'Ringing' -- Executing [1688@did:4] Ringing("SIP/192.168.200.11-b3506dc0", "") in new stack [Apr 7 16:24:39] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'SIP/2.0 18' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:39] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'Wait' -- Executing [1688@did:5] Wait("SIP/192.168.200.11-b3506dc0", "3") in new stack [Apr 7 16:24:42] DEBUG[24448]: pbx.c:3057 pbx_substitute_variables_helper_full: Expression result is '1' [Apr 7 16:24:42] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'GotoIf' -- Executing [1688@did:6] GotoIf("SIP/192.168.200.11-b3506dc0", "1?30:") in new stack -- Goto (did,1688,30)> [Apr 7 16:24:42] DEBUG[24448]: pbx.c:3156 pbx_extension_helper: Launching 'Dial' -- Executing [1688@did:30] Dial("SIP/192.168.200.11-b3506dc0", "SIP/sip1688&SIP/688,17") in new stack [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:20845 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) == Using SIP RTP CoS mark 5 [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:6286 sip_alloc: Allocating new SIP dialog for 417e60bb671904e9566b43a0756d534f@127.0.1.1 - INVITE (With RTP) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:4187 do_setnat: Setting NAT on RTP to Off [Apr 7 16:24:42] DEBUG[24448]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:5706 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:5707 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:5708 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:5709 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:5711 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:5739 sip_new: This channel will not be able to handle video. [Apr 7 16:24:42] DEBUG[24448]: rtp.c:2164 ast_rtp_make_compatible: Seeded SDP of 'SIP/sip1688-094043e8' with that of 'SIP/192.168.200.11-b3506dc0' [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 7 16:24:42] DEBUG[24448]: channel.c:3871 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:4576 sip_call: Outgoing Call for sip1688 [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:4773 update_call_counter: Updating call counter for outgoing call [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:4598 sip_call: Our T38 capability (0), joint T38 capability (0) [Apr 7 16:24:42] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:24:42] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:8643 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False Text flag: False [Apr 7 16:24:42] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/sip1688 - state 6 (Ringing) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:8644 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 7 16:24:42] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/sip1688' state '6' [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:8797 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:24:42] DEBUG[24448]: channel.c:2822 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:8862 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:2627 initialize_initreq: Initializing initreq for method INVITE - callid 3739fac026b192b346e00dcc268ece07@192.168.100.180 [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:24:42] DEBUG[23187]: 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. -- Called sip1688*CLI> [Apr 7 16:24:42] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/sip1688' [Apr 7 16:24:42] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'Ringing' for 'SIP/sip1688' [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:20845 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 7 16:24:42] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 6 == Using SIP RTP CoS mark 5 [Apr 7 16:24:42] DEBUG[23183]: devicestate.c:654 process_collection: Aggregate state for device 'SIP/sip1688' has changed to 'Ringing' [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:6286 sip_alloc: Allocating new SIP dialog for 6b85106e341d7e5b4b053f4d21b6f60c@127.0.1.1 - INVITE (With RTP) [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:20926 sip_request_call: Cant create SIP call - target device not registred [Apr 7 16:24:42] DEBUG[24448]: chan_sip.c:4914 sip_destroy: Destroying SIP dialog 6b85106e341d7e5b4b053f4d21b6f60c@127.0.1.1 [Apr 7 16:24:42] WARNING[24448]: app_dial.c:1534 dial_exec_full: Unable to create channel of type 'SIP' (cause 20 - Unknown) [Apr 7 16:24:42] DEBUG[23195]: chan_sip.c:3397 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3739fac026b192b346e00dcc268ece07@192.168.100.180' Request 102: Found [Apr 7 16:24:42] DEBUG[23195]: chan_sip.c:15659 handle_response_invite: SIP response 100 to standard invite [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3397 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3739fac026b192b346e00dcc268ece07@192.168.100.180' Request 102: Found [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:15659 handle_response_invite: SIP response 180 to standard invite [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:24:43] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/sip1688 - state 6 (Ringing) [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/sip1688' state '6' -- SIP/sip1688-094043e8 is ringing [Apr 7 16:24:43] DEBUG[23187]: 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:24:43] DEBUG[23185]: chan_sip.c:2863 __sip_xmit: Trying to put 'NOTIFY sip' onto UDP socket destined for 192.168.101.250:5060 == Extension Changed 1688[did] new state Ringing for Notify User sip1688 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[24448]: rtp.c:2091 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/192.168.200.11-b3506dc0' with that of 'SIP/sip1688-094043e8' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'Ringing' for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 6 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:648 process_collection: Aggregate state for device 'SIP/sip1688' has not changed from 'Ringing' [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'SIP/2.0 18' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3320 __sip_ack: Acked pending invite 106 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on 'df846566-a742efff-5de72900@192.168.101.250' of Request 106: Match Found [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3320 __sip_ack: Acked pending invite 102 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on '3739fac026b192b346e00dcc268ece07@192.168.100.180' of Request 102: Match Found [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:15659 handle_response_invite: SIP response 200 to standard invite [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:7504 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:7509 process_sdp: We have an owner, now see if we need to change this call [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:4773 update_call_counter: Updating call counter for outgoing call [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:10761 build_route: build_route: Contact hop: [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:24:43] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/sip1688 - state 2 (In use) [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:2863 __sip_xmit: Trying to put 'ACK sip:si' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/sip1688' state '2' [Apr 7 16:24:43] DEBUG[23187]: 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:24:43] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'In use' for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 2 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:654 process_collection: Aggregate state for device 'SIP/sip1688' has changed to 'In use' -- SIP/sip1688-094043e8 answered SIP/192.168.200.11-b3506dc0 [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:24:43] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/sip1688 - state 2 (In use) [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/sip1688' state '2' [Apr 7 16:24:43] DEBUG[23187]: 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:24:43] DEBUG[23185]: chan_sip.c:2863 __sip_xmit: Trying to put 'NOTIFY sip' onto UDP socket destined for 192.168.101.250:5060 == Extension Changed 1688[did] new state InUse for Notify User sip1688 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'In use' for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 2 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:648 process_collection: Aggregate state for device 'SIP/sip1688' has not changed from 'In use' [Apr 7 16:24:43] DEBUG[24448]: rtp.c:2091 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/192.168.200.11-b3506dc0' with that of 'SIP/sip1688-094043e8' [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:5300 sip_answer: SIP answering channel: SIP/192.168.200.11-b3506dc0 [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - 192.168.200.11 [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8926 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 7 16:24:43] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer 192.168.200.11 [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8643 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8644 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8797 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:24:43] DEBUG[24448]: channel.c:2822 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8862 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:43] DEBUG[23184]: channel.c:1178 channel_find_locked: Avoiding initial deadlock for channel '0xb3519960' [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/192.168.200.11 - state 2 (In use) [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/192.168.200.11' state '2' [Apr 7 16:24:43] DEBUG[23187]: 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:24:43] DEBUG[23195]: chan_sip.c:19477 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' of Response 101: Match Found [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/192.168.200.11' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'In use' for 'SIP/192.168.200.11' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 2 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:648 process_collection: Aggregate state for device 'SIP/192.168.200.11' has not changed from 'In use' [Apr 7 16:24:43] DEBUG[24448]: features.c:2244 ast_bridge_call: bridge answer set, chan answer set -- Native bridging SIP/192.168.200.11-b3506dc0 and SIP/sip1688-094043e8 [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:22952 sip_set_rtp_peer: Sending reinvite on SIP 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' - It's audio soon redirected to IP 192.168.101.250 [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8643 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8644 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8797 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:24:43] DEBUG[24448]: channel.c:2822 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8862 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:2625 initialize_initreq: Initializing already initialized SIP dialog a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 (presumably reinvite) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:22952 sip_set_rtp_peer: Sending reinvite on SIP '3739fac026b192b346e00dcc268ece07@192.168.100.180' - It's audio soon redirected to IP 192.168.200.10 [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8643 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8644 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8797 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:24:43] DEBUG[24448]: channel.c:2822 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=38) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:8862 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:2625 initialize_initreq: Initializing already initialized SIP dialog 3739fac026b192b346e00dcc268ece07@192.168.100.180 (presumably reinvite) [Apr 7 16:24:43] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3397 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' Request 102: Found [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:15657 handle_response_invite: SIP response 100 to RE-invite on outgoing call a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3320 __sip_ack: Acked pending invite 102 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' of Request 102: Match Found [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:15657 handle_response_invite: SIP response 200 to RE-invite on outgoing call a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:6937 process_sdp: SDP version number same as previous SDP [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:4773 update_call_counter: Updating call counter for incoming call [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:15787 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:2863 __sip_xmit: Trying to put 'ACK sip:28' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3320 __sip_ack: Acked pending invite 107 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on 'df846566-a742efff-5de72900@192.168.101.250' of Request 107: Match Found [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3320 __sip_ack: Acked pending invite 103 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on '3739fac026b192b346e00dcc268ece07@192.168.100.180' of Request 103: Match Found [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:15657 handle_response_invite: SIP response 200 to RE-invite on outgoing call 3739fac026b192b346e00dcc268ece07@192.168.100.180 [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:7504 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:7509 process_sdp: We have an owner, now see if we need to change this call [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:4773 update_call_counter: Updating call counter for outgoing call [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:24:43] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/sip1688 - state 2 (In use) [Apr 7 16:24:43] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/sip1688' state '2' [Apr 7 16:24:43] DEBUG[23187]: 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:24:43] DEBUG[23195]: chan_sip.c:15787 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Apr 7 16:24:43] DEBUG[23195]: chan_sip.c:2863 __sip_xmit: Trying to put 'ACK sip:si' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'In use' for 'SIP/sip1688' [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 2 [Apr 7 16:24:43] DEBUG[23183]: devicestate.c:648 process_collection: Aggregate state for device 'SIP/sip1688' has not changed from 'In use' /* app_voicemail.c content removed as it was not necessary... */ [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:19477 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:2638 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 3739fac026b192b346e00dcc268ece07@192.168.100.180 [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:18980 handle_request_bye: Received bye, issuing owner hangup [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:2863 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.101.250:5060 [Apr 7 16:24:47] DEBUG[24448]: rtp.c:3884 bridge_native_loop: Oooh, got a hangup [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:22952 sip_set_rtp_peer: Sending reinvite on SIP 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' - It's audio soon redirected to IP 192.168.100.180 [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:8643 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:8644 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:8797 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:24:47] DEBUG[24448]: channel.c:2822 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34) [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:8862 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:2625 initialize_initreq: Initializing already initialized SIP dialog a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 (presumably reinvite) [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:47] DEBUG[24448]: channel.c:4677 ast_channel_bridge: Returning from native bridge, channels: SIP/192.168.200.11-b3506dc0, SIP/sip1688-094043e8 [Apr 7 16:24:47] DEBUG[24448]: channel.c:1638 ast_hangup: Hanging up channel 'SIP/sip1688-094043e8' [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:5124 sip_hangup: Hangup call SIP/sip1688-094043e8, SIP callid 3739fac026b192b346e00dcc268ece07@192.168.100.180 [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:4773 update_call_counter: Updating call counter for outgoing call [Apr 7 16:24:47] DEBUG[23184]: devicestate.c:364 _ast_device_state: No provider found, checking channel drivers for SIP - sip1688 [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:3397 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' Request 103: Found [Apr 7 16:24:47] DEBUG[23184]: chan_sip.c:20751 sip_devicestate: Checking device state for peer sip1688 [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:15657 handle_response_invite: SIP response 100 to RE-invite on outgoing call a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 [Apr 7 16:24:47] DEBUG[24448]: devicestate.c:456 devstate_event: device 'SIP/sip1688' state '1' [Apr 7 16:24:47] DEBUG[23184]: devicestate.c:481 do_state_change: Changing state for SIP/sip1688 - state 1 (Not in use) [Apr 7 16:24:47] DEBUG[23184]: devicestate.c:456 devstate_event: device 'SIP/sip1688' state '1' [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:4914 sip_destroy: Destroying SIP dialog 3739fac026b192b346e00dcc268ece07@192.168.100.180 [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:3320 __sip_ack: Acked pending invite 103 [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' of Request 103: Match Found [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:15657 handle_response_invite: SIP response 200 to RE-invite on outgoing call a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:6937 process_sdp: SDP version number same as previous SDP [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:4773 update_call_counter: Updating call counter for incoming call [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:2863 __sip_xmit: Trying to put 'ACK sip:28' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:47] DEBUG[24448]: rtp.c:2041 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/sip1688' [Apr 7 16:24:47] DEBUG[23187]: 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:24:47] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'Not in use' for 'SIP/sip1688' [Apr 7 16:24:47] DEBUG[23187]: 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:24:47] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 1 [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:654 process_collection: Aggregate state for device 'SIP/sip1688' has changed to 'Not in use' [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/sip1688' [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'Not in use' for 'SIP/sip1688' [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 1 [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:648 process_collection: Aggregate state for device 'SIP/sip1688' has not changed from 'Not in use' [Apr 7 16:24:47] DEBUG[24448]: app_dial.c:2064 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 7 16:24:47] DEBUG[24448]: pbx.c:3748 __ast_pbx_run: Spawn extension (did,1688,30) exited non-zero on 'SIP/192.168.200.11-b3506dc0' == Spawn extension (did, 1688, 30) exited non-zero on 'SIP/192.168.200.11-b3506dc0' [Apr 7 16:24:47] DEBUG[24448]: channel.c:1543 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/192.168.200.11-b3506dc0' [Apr 7 16:24:47] DEBUG[24448]: channel.c:1638 ast_hangup: Hanging up channel 'SIP/192.168.200.11-b3506dc0' [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:5124 sip_hangup: Hangup call SIP/192.168.200.11-b3506dc0, SIP callid a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:20308 stop_session_timer: Session timer stopped: -1 - a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 [Apr 7 16:24:47] DEBUG[24448]: chan_sip.c:2863 __sip_xmit: Trying to put 'BYE sip:28' onto UDP socket destined for 192.168.200.11:5060 [Apr 7 16:24:47] DEBUG[24448]: devicestate.c:456 devstate_event: device 'SIP/192.168.200.11' state '1' [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:676 handle_devstate_change: Processing device state change for 'SIP/192.168.200.11' [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:626 process_collection: Adding per-server state of 'Not in use' for 'SIP/192.168.200.11' [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:632 process_collection: Aggregate devstate result is 1 [Apr 7 16:24:47] DEBUG[23183]: devicestate.c:654 process_collection: Aggregate state for device 'SIP/192.168.200.11' has changed to 'Not in use' [Apr 7 16:24:47] DEBUG[23187]: 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:24:47] DEBUG[23195]: chan_sip.c:3357 __sip_ack: Stopping retransmission on 'a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11' of Request 104: Match Found [Apr 7 16:24:47] DEBUG[23195]: chan_sip.c:4914 sip_destroy: Destroying SIP dialog a57a7400-1df141c6-681e-bc8a8c0@192.168.200.11 MJLM-Hou-AsteriVOX-00*CLI> core set debug 0 Core debug is now OFF*CLI> == Extension Changed 1688[did] new state Idle for Notify User sip1688 MJLM-Hou-AsteriVOX-00*CLI>