Asterisk*CLI> [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:2763 do_setnat: Setting NAT on RTP to Off [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:4584 sip_alloc: Allocating new SIP dialog for 00075079-cab50023-05dfd519-71569dee@10.10.100.244 - INVITE (With RTP) [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:2763 do_setnat: Setting NAT on RTP to Off [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:2201 __sip_ack: Stopping retransmission on '00075079-cab50023-05dfd519-71569dee@10.10.100.244' of Response 101: Match Found [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:2763 do_setnat: Setting NAT on RTP to Off [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:5502 process_sdp: T38 state changed to 0 on channel [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:5582 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:14355 handle_request_invite: Checking SIP call limits for device 3956 [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:3224 update_call_counter: Updating call counter for incoming call [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:4061 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:4062 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:4063 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:4064 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:4087 sip_new: This channel will not be able to handle video. [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:8412 build_route: build_route: Contact hop: [Feb 10 14:01:53] DEBUG[22371]: chan_sip.c:14438 handle_request_invite: SIP/3956-0a011970: New call is still down.... Trying... [Feb 10 14:01:53] DEBUG[22371]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3956 [Feb 10 14:01:53] DEBUG[22366]: chan_sip.c:16376 sip_devicestate: Checking device state for peer 3956 [Feb 10 14:01:53] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for SIP/3956 - state 1 (Not in use) [Feb 10 14:01:53] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'SIP/3956' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 10 14:01:53] DEBUG[22589]: pbx.c:1842 pbx_extension_helper: Launching 'Goto' -- Executing [3998@SIP_In:1] Goto("SIP/3956-0a011970", "extensions|3998|1") in new stack -- Goto (extensions,3998,1) [Feb 10 14:01:53] DEBUG[22589]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [3998@extensions:1] Set("SIP/3956-0a011970", "CALLERID(name)=JOES POOL HALL") in new stack [Feb 10 14:01:53] DEBUG[22589]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [3998@extensions:2] Set("SIP/3956-0a011970", "CALLERID(num)=8168063672") in new stack [Feb 10 14:01:53] DEBUG[22589]: pbx.c:1842 pbx_extension_helper: Launching 'Dial' -- Executing [3998@extensions:3] Dial("SIP/3956-0a011970", "DAHDI/g14/9999999999") in new stack [Feb 10 14:01:53] DEBUG[22589]: chan_dahdi.c:8067 dahdi_request: Using channel 169 [Feb 10 14:01:53] DEBUG[22589]: rtp.c:1585 ast_rtp_make_compatible: Channel 'DAHDI/169-1' has no RTP, not doing anything [Feb 10 14:01:53] DEBUG[22589]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 10 14:01:53] DEBUG[22589]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 10 14:01:53] DEBUG[22589]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 10 14:01:53] DEBUG[22589]: channel.c:3351 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 10 14:01:53] DEBUG[22589]: chan_dahdi.c:1999 dahdi_call: Dialing '9999999999' [Feb 10 14:01:53] DEBUG[22589]: chan_dahdi.c:2077 dahdi_call: Deferring dialing... [Feb 10 14:01:53] DEBUG[22589]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel DAHDI/169 -- Called g14/9999999999 [Feb 10 14:01:53] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for DAHDI/169 - state 2 (In use) [Feb 10 14:01:53] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'DAHDI/169' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 10 14:01:54] DEBUG[22589]: chan_dahdi.c:4728 __dahdi_exception: Exception on 170, channel 169 [Feb 10 14:01:54] DEBUG[22589]: chan_dahdi.c:3825 dahdi_handle_event: Got event Wink/Flash(3) on channel 169 (index 0) [Feb 10 14:01:54] DEBUG[22589]: chan_dahdi.c:4500 dahdi_handle_event: Ignoring wink on channel 169 [Feb 10 14:01:54] DEBUG[22589]: chan_dahdi.c:4728 __dahdi_exception: Exception on 170, channel 169 [Feb 10 14:01:54] DEBUG[22589]: chan_dahdi.c:3825 dahdi_handle_event: Got event Hook Transition Complete(12) on channel 169 (index 0) [Feb 10 14:01:54] DEBUG[22589]: chan_dahdi.c:4563 dahdi_handle_event: Sent deferred digit string: T9999999999w [Feb 10 14:01:57] DEBUG[22589]: chan_dahdi.c:4728 __dahdi_exception: Exception on 170, channel 169 [Feb 10 14:01:57] DEBUG[22589]: chan_dahdi.c:3825 dahdi_handle_event: Got event Dial Complete(9) on channel 169 (index 0) [Feb 10 14:01:57] DEBUG[22589]: chan_dahdi.c:1485 dahdi_enable_ec: Enabled echo cancellation on channel 169 [Feb 10 14:01:57] DEBUG[22589]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel DAHDI/169 [Feb 10 14:01:57] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for DAHDI/169 - state 6 (Ringing) [Feb 10 14:01:57] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'DAHDI/169' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 10 14:01:57] DEBUG[22589]: chan_sip.c:6784 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 10 14:01:57] DEBUG[22589]: chan_sip.c:6548 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 10 14:01:57] DEBUG[22589]: chan_sip.c:6549 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 10 14:01:57] DEBUG[22589]: chan_sip.c:6680 add_sdp: -- Done with adding codecs to SDP [Feb 10 14:01:57] DEBUG[22589]: chan_sip.c:6725 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 10 14:01:57] DEBUG[22589]: rtp.c:2774 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 10 14:01:57] DEBUG[22589]: rtp.c:2791 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 10 14:02:01] DEBUG[22589]: chan_dahdi.c:4728 __dahdi_exception: Exception on 170, channel 169 [Feb 10 14:02:01] DEBUG[22589]: chan_dahdi.c:3825 dahdi_handle_event: Got event Ring/Answered(2) on channel 169 (index 0) [Feb 10 14:02:01] DEBUG[22589]: chan_dahdi.c:4223 dahdi_handle_event: Line answered [Feb 10 14:02:01] DEBUG[22589]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel DAHDI/169 -- DAHDI/169-1 answered SIP/3956-0a011970 [Feb 10 14:02:01] DEBUG[22589]: rtp.c:1510 ast_rtp_early_bridge: Channel 'DAHDI/169-1' has no RTP, not doing anything [Feb 10 14:02:01] DEBUG[22589]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3956 [Feb 10 14:02:01] DEBUG[22589]: chan_sip.c:3698 sip_answer: SIP answering channel: SIP/3956-0a011970 [Feb 10 14:02:01] DEBUG[22589]: chan_sip.c:6784 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 10 14:02:01] DEBUG[22589]: chan_sip.c:6548 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 10 14:02:01] DEBUG[22366]: channel.c:1088 channel_find_locked: Avoiding initial deadlock for channel '0xa0160a0' [Feb 10 14:02:01] DEBUG[22589]: chan_sip.c:6549 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 10 14:02:01] DEBUG[22589]: chan_sip.c:6680 add_sdp: -- Done with adding codecs to SDP [Feb 10 14:02:01] DEBUG[22589]: chan_sip.c:6725 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 10 14:02:01] DEBUG[22589]: chan_dahdi.c:5154 dahdi_indicate: Requested indication 20 on channel DAHDI/169-1 [Feb 10 14:02:01] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for DAHDI/169 - state 2 (In use) [Feb 10 14:02:01] DEBUG[22366]: chan_sip.c:16376 sip_devicestate: Checking device state for peer 3956 [Feb 10 14:02:01] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for SIP/3956 - state 1 (Not in use) [Feb 10 14:02:01] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'DAHDI/169' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 10 14:02:01] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'SIP/3956' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 10 14:02:01] DEBUG[22589]: rtp.c:2791 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 10 14:02:01] DEBUG[22371]: chan_sip.c:2201 __sip_ack: Stopping retransmission on '00075079-cab50023-05dfd519-71569dee@10.10.100.244' of Response 102: Match Found [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:5502 process_sdp: T38 state changed to 0 on channel SIP/3956-0a011970 [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:5582 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:14512 handle_request_invite: SIP/3956-0a011970: This call is UP.... [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:6784 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:6548 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:6549 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:6680 add_sdp: -- Done with adding codecs to SDP [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:6725 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 10 14:02:06] DEBUG[22589]: chan_dahdi.c:5154 dahdi_indicate: Requested indication 16 on channel DAHDI/169-1 -- Music class default requested but no musiconhold loaded. [Feb 10 14:02:06] DEBUG[22371]: chan_sip.c:2201 __sip_ack: Stopping retransmission on '00075079-cab50023-05dfd519-71569dee@10.10.100.244' of Response 103: Match Found [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:5502 process_sdp: T38 state changed to 0 on channel SIP/3956-0a011970 [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:5582 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:14512 handle_request_invite: SIP/3956-0a011970: This call is UP.... [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:6784 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:6548 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:6549 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:6680 add_sdp: -- Done with adding codecs to SDP [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:6725 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 10 14:02:09] DEBUG[22589]: chan_dahdi.c:5154 dahdi_indicate: Requested indication 17 on channel DAHDI/169-1 [Feb 10 14:02:09] DEBUG[22589]: rtp.c:2791 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 10 14:02:09] DEBUG[22589]: rtp.c:2637 ast_rtp_raw_write: Difference is 25920, ms is 3260 [Feb 10 14:02:09] DEBUG[22371]: chan_sip.c:2201 __sip_ack: Stopping retransmission on '00075079-cab50023-05dfd519-71569dee@10.10.100.244' of Response 104: Match Found [Feb 10 14:02:12] DEBUG[22371]: chan_sip.c:1665 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 00075079-cab50023-05dfd519-71569dee@10.10.100.244 [Feb 10 14:02:12] DEBUG[22371]: chan_sip.c:15236 handle_request_bye: Received bye, issuing owner hangup [Feb 10 14:02:12] DEBUG[22589]: channel.c:3839 ast_generic_bridge: Didn't get a frame from channel: SIP/3956-0a011970 [Feb 10 14:02:12] DEBUG[22589]: chan_dahdi.c:5154 dahdi_indicate: Requested indication 20 on channel DAHDI/169-1 [Feb 10 14:02:12] DEBUG[22589]: channel.c:4182 ast_channel_bridge: Bridge stops bridging channels SIP/3956-0a011970 and DAHDI/169-1 [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '"JOES POOL HALL" <3956>' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '3956' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '3998' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'extensions' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/3956-0a011970' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DAHDI/169-1' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DAHDI/g14/9999999999' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-02-10 14:01:53' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-02-10 14:02:01' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-02-10 14:02:12' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '19' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '11' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1234292513.26' [Feb 10 14:02:12] DEBUG[22589]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Feb 10 14:02:12] DEBUG[22589]: channel.c:1505 ast_hangup: Hanging up channel 'DAHDI/169-1' [Feb 10 14:02:12] DEBUG[22589]: chan_dahdi.c:2516 dahdi_hangup: dahdi_hangup(DAHDI/169-1) [Feb 10 14:02:12] DEBUG[22589]: chan_dahdi.c:2550 dahdi_hangup: Hangup: channel: 169 index = 0, normal = 170, callwait = -1, thirdcall = -1 [Feb 10 14:02:12] DEBUG[22589]: chan_dahdi.c:1517 dahdi_disable_ec: disabled echo cancellation on channel 169 [Feb 10 14:02:12] DEBUG[22589]: chan_dahdi.c:2986 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/169-1 [Feb 10 14:02:12] DEBUG[22589]: chan_dahdi.c:1453 update_conf: Updated conferencing on 169, with 0 conference users -- Hungup 'DAHDI/169-1' [Feb 10 14:02:12] DEBUG[22589]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel DAHDI/169 [Feb 10 14:02:12] DEBUG[22589]: rtp.c:1510 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 10 14:02:12] DEBUG[22589]: app_dial.c:1815 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 10 14:02:12] DEBUG[22589]: pbx.c:2425 __ast_pbx_run: Spawn extension (extensions,3998,3) exited non-zero on 'SIP/3956-0a011970' == Spawn extension (extensions, 3998, 3) exited non-zero on 'SIP/3956-0a011970' [Feb 10 14:02:12] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for DAHDI/169 - state 0 (Unknown) [Feb 10 14:02:12] DEBUG[22589]: channel.c:1412 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/3956-0a011970' [Feb 10 14:02:12] DEBUG[22589]: channel.c:1505 ast_hangup: Hanging up channel 'SIP/3956-0a011970' [Feb 10 14:02:12] DEBUG[22589]: chan_sip.c:3537 sip_hangup: Hangup call SIP/3956-0a011970, SIP callid 00075079-cab50023-05dfd519-71569dee@10.10.100.244) [Feb 10 14:02:12] DEBUG[22589]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3956 [Feb 10 14:02:12] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'DAHDI/169' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Feb 10 14:02:12] DEBUG[22366]: chan_sip.c:16376 sip_devicestate: Checking device state for peer 3956 [Feb 10 14:02:12] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for SIP/3956 - state 1 (Not in use) [Feb 10 14:02:12] DEBUG[22379]: chan_dahdi.c:7112 do_monitor: Monitor doohicky got event On hook on channel 169 [Feb 10 14:02:12] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'SIP/3956' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 10 14:02:12] DEBUG[22379]: chan_dahdi.c:1517 dahdi_disable_ec: disabled echo cancellation on channel 169 Really destroying SIP dialog '00075079-cab50023-05dfd519-71569dee@10.10.100.244' Method: BYE [Feb 10 14:02:36] DEBUG[22383]: chan_iax2.c:8018 socket_process: Peer IAX_15100: got pong, lastms 135, historicms 135, maxms 2000 [Feb 10 14:03:22] DEBUG[22371]: chan_sip.c:4584 sip_alloc: Allocating new SIP dialog for d9917ef6ac71fd8b - REGISTER (No RTP) [Feb 10 14:03:22] DEBUG[22371]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2600-57i [Feb 10 14:03:22] DEBUG[22366]: chan_sip.c:16376 sip_devicestate: Checking device state for peer 2600-57i [Feb 10 14:03:22] DEBUG[22366]: devicestate.c:287 do_state_change: Changing state for SIP/2600-57i - state 1 (Not in use) [Feb 10 14:03:22] DEBUG[22396]: app_queue.c:661 handle_statechange: Device 'SIP/2600-57i' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 10 14:03:36] DEBUG[22388]: chan_iax2.c:8018 socket_process: Peer IAX_15100: got pong, lastms 134, historicms 134, maxms 2000 [Feb 10 14:03:54] DEBUG[22371]: chan_sip.c:2104 __sip_autodestruct: Auto destroying SIP dialog 'd9917ef6ac71fd8b' [Feb 10 14:03:54] DEBUG[22371]: chan_sip.c:3333 sip_destroy: Destroying SIP dialog d9917ef6ac71fd8b Really destroying SIP dialog 'd9917ef6ac71fd8b' Method: REGISTER [Feb 10 14:04:36] DEBUG[22383]: chan_iax2.c:8018 socket_process: Peer IAX_15100: got pong, lastms 143, historicms 143, maxms 2000