############################### Before Call: mit2*CLI> sip show subscriptions Peer User Call ID Extension Last state Type Mailbox 0 active SIP subscriptions mit2*CLI> -= Registered Asterisk Dial Plan Hints =- 4302@default : SIP/138 State:Idle Watchers 0 4308@default : SIP/7777 State:Idle Watchers 0 ---------------- - 2 hints registered ############################### Calling: SIP/138 to SIP/7777 [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:4454 sip_alloc: Allocating new SIP dialog for 39765d15-135b1f42-972f4a4b@192.168.0.155 - INVITE (With RTP) [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:5305 process_sdp: T38 state changed to 0 on channel [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:5385 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:13639 handle_request_invite: Checking SIP call limits for device 138 [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:3210 update_call_counter: Call from user '138' is 1 out of 8 [Oct 31 20:20:43] DEBUG[26551]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:3948 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:3949 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:3950 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Oct 31 20:20:43] DEBUG[26551]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:3951 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:3974 sip_new: This channel will not be able to handle video. [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:8144 build_route: build_route: Contact hop: [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:13718 handle_request_invite: SIP/138-08214d48: New call is still down.... Trying... [Oct 31 20:20:43] DEBUG[26551]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138-08214d48 [Oct 31 20:20:43] DEBUG[26602]: pbx.c:1809 pbx_extension_helper: Launching 'Dial' -- Executing [4308@default:1] Dial("SIP/138-08214d48", "SIP/7777") in new stack [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:15654 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:4454 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Oct 31 20:20:43] DEBUG[26602]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3948 sip_new: *** Our native formats are 0x80004 (ulaw|h263) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3949 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3950 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Oct 31 20:20:43] DEBUG[26602]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3951 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3953 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3974 sip_new: This channel will not be able to handle video. [Oct 31 20:20:43] DEBUG[26602]: channel.c:3534 ast_channel_inherit_variables: Not copying variable STACK-default-4308-1. [Oct 31 20:20:43] DEBUG[26602]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 31 20:20:43] DEBUG[26602]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 31 20:20:43] DEBUG[26602]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 31 20:20:43] DEBUG[26602]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPURI. [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:2953 sip_call: Outgoing Call for 7777 [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:3210 update_call_counter: Call to peer '7777' is 1 out of 1 [Oct 31 20:20:43] DEBUG[26602]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777 [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:2968 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:6342 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:6343 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:6360 add_sdp: This call needs video offers, but there's no video support enabled! [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:6474 add_sdp: -- Done with adding codecs to SDP [Oct 31 20:20:43] DEBUG[26602]: channel.c:2547 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 ch an->timingfd=35) [Oct 31 20:20:43] DEBUG[26602]: chan_sip.c:6519 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h2 63) [Oct 31 20:20:43] DEBUG[26602]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! -- Called 7777 [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:20:43] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 1 (Not in use) [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:20:43] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:43] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 6 (Ringing) [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:43] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:43] DEBUG[26603]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '1' (Not in use) but we don't care b ecause they're not a member of any queue. [Oct 31 20:20:43] DEBUG[26604]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '6' (Ringing) but we don't care bec ause they're not a member of any queue. [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 4f12ac744a9747dd686af9d609ddaacd@192.168.0.10 Thei r Tag Our tag: as559d7177 [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4f1 2ac744a9747dd686af9d609ddaacd@192.168.0.10' Request 102: Found [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:11818 handle_response_invite: SIP response 100 to standard invite [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 4f12ac744a9747dd686af9d609ddaacd@192.168.0.10 Thei r Tag 1374335209 Our tag: as559d7177 [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4f1 2ac744a9747dd686af9d609ddaacd@192.168.0.10' Request 102: Found [Oct 31 20:20:43] DEBUG[26551]: chan_sip.c:11818 handle_response_invite: SIP response 180 to standard invite [Oct 31 20:20:43] DEBUG[26551]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777-08218cb8 -- SIP/7777-08218cb8 is ringing [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:43] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 6 (Ringing) [Oct 31 20:20:43] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:43] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:43] DEBUG[26605]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '6' (Ringing) but we don't care bec ause they're not a member of any queue. mit2*CLI> sip show subscriptions Peer User Call ID Extension Last state Type Mailbox 0 active SIP subscriptions mit2*CLI> core show hints mit2*CLI> -= Registered Asterisk Dial Plan Hints =- 4302@default : SIP/138 State:Idle Watchers 0 4308@default : SIP/7777 State:Ringing Watchers 0 ---------------- - 2 hints registered ################################ Call Answered: [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 4f12ac744a9747dd686af9d609ddaacd@192.168.0.10 Thei r Tag 1374335209 Our tag: as559d7177 [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:2140 __sip_ack: Acked pending invite 102 [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '4f12ac744a9747dd686af9d609ddaacd@192.168.0.10 ' of Request 102: Match Not Found [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:11818 handle_response_invite: SIP response 200 to standard invite [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:5305 process_sdp: T38 state changed to 0 on channel SIP/7777-08218cb8 [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:5385 process_sdp: We're settling with these formats: 0x8 (alaw) [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:5392 process_sdp: We have an owner, now see if we need to change this call [Oct 31 20:20:53] DEBUG[26551]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:20:53] DEBUG[26551]: channel.c:3024 set_format: Set channel SIP/7777-08218cb8 to read format ulaw [Oct 31 20:20:53] DEBUG[26551]: channel.c:3024 set_format: Set channel SIP/7777-08218cb8 to write format ulaw [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 31 20:20:53] DEBUG[26551]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777 [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:8144 build_route: build_route: Contact hop: [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:53] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 3 (Busy) [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:53] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:53] DEBUG[26602]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777-08218cb8 -- SIP/7777-08218cb8 answered SIP/138-08214d48 [Oct 31 20:20:53] DEBUG[26602]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138-08214d48 [Oct 31 20:20:53] DEBUG[26602]: chan_sip.c:3602 sip_answer: SIP answering channel: SIP/138-08214d48 [Oct 31 20:20:53] DEBUG[26602]: chan_sip.c:6578 transmit_response_with_sdp: Setting framing from config on incoming call [Oct 31 20:20:53] DEBUG[26602]: chan_sip.c:6342 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Oct 31 20:20:53] DEBUG[26602]: chan_sip.c:6343 add_sdp: ** Our prefcodec: 0x0 (nothing) [Oct 31 20:20:53] DEBUG[26602]: chan_sip.c:6474 add_sdp: -- Done with adding codecs to SDP [Oct 31 20:20:53] DEBUG[26602]: channel.c:2547 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 ch an->timingfd=32) [Oct 31 20:20:53] DEBUG[26602]: chan_sip.c:6519 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Oct 31 20:20:53] DEBUG[26602]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:53] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 3 (Busy) [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:20:53] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:20:53] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 1 (Not in use) [Oct 31 20:20:53] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:20:53] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:20:53] DEBUG[26606]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '3' (Busy) but we don't care becaus e they're not a member of any queue. [Oct 31 20:20:53] DEBUG[26607]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '3' (Busy) but we don't care becaus e they're not a member of any queue. [Oct 31 20:20:53] DEBUG[26608]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '1' (Not in use) but we don't care b ecause they're not a member of any queue. [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: 4f12ac744a9747dd686af9d609ddaacd@192.168.0.10 T heir Tag 1374335209 Our tag: as559d7177 [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 39765d15-135b1f42-972f4a4b@192.168.0.155 Their Tag E214980-B1305BF1 Our tag: as53b62593 [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 31 20:20:53] DEBUG[26551]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '39765d15-135b1f42-972f4a4b@192.168.0.155' of Response 1: Match Not Found [Oct 31 20:20:53] DEBUG[26602]: rtp.c:2731 ast_rtp_write: Ooh, format changed from unknown to ulaw [Oct 31 20:20:53] DEBUG[26602]: rtp.c:2748 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Oct 31 20:20:53] DEBUG[26602]: rtp.c:2731 ast_rtp_write: Ooh, format changed from unknown to alaw [Oct 31 20:20:53] DEBUG[26602]: rtp.c:2748 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 mit2*CLI> core show hints mit2*CLI> -= Registered Asterisk Dial Plan Hints =- 4302@default : SIP/138 State:Idle Watchers 0 4308@default : SIP/7777 State:Busy Watchers 0 ---------------- - 2 hints registered mit2*CLI> sip show subscriptions Peer User Call ID Extension Last state Type Mailbox 0 active SIP subscriptions [Oct 31 20:20:57] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: 4f12ac744a9747dd686af9d609ddaacd@192.168.0.10 T heir Tag 1374335209 Our tag: as559d7177 [Oct 31 20:20:57] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: 39765d15-135b1f42-972f4a4b@192.168.0.155 Their Tag E214980-B1305BF1 Our tag: as53b62593 [Oct 31 20:20:57] DEBUG[26551]: chan_sip.c:15145 sipsock_read: Invalid SIP message - rejected , no callid, len 422 [Oct 31 20:20:58] DEBUG[26602]: rtp.c:879 ast_rtcp_read: Got RTCP report of 80 bytes mit2*CLI> mit2*CLI> [Oct 31 20:20:59] DEBUG[26540]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 483! ################################ Call Ended: [Oct 31 20:21:03] DEBUG[26602]: rtp.c:879 ast_rtcp_read: Got RTCP report of 80 bytes [Oct 31 20:21:04] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 4f12ac744a9747dd686af9d609ddaacd@192.168.0.10 Thei r Tag 1374335209 Our tag: as559d7177 [Oct 31 20:21:04] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received BYE (8) - Command in SIP BYE [Oct 31 20:21:04] DEBUG[26551]: chan_sip.c:1646 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 4f12ac744a9747dd686af9d609ddaacd@ 192.168.0.10 [Oct 31 20:21:04] DEBUG[26551]: chan_sip.c:14503 handle_request_bye: Received bye, issuing owner hangup [Oct 31 20:21:04] DEBUG[26602]: channel.c:4034 ast_generic_bridge: Didn't get a frame from channel: SIP/7777-08218cb8 [Oct 31 20:21:04] DEBUG[26602]: channel.c:4358 ast_channel_bridge: Bridge stops bridging channels SIP/138-08214d48 and SIP/7777-0821 8cb8 [Oct 31 20:21:04] DEBUG[26602]: channel.c:1762 ast_hangup: Hanging up channel 'SIP/7777-08218cb8' [Oct 31 20:21:04] DEBUG[26602]: chan_sip.c:3445 sip_hangup: Hangup call SIP/7777-08218cb8, SIP callid 4f12ac744a9747dd686af9d609ddaa cd@192.168.0.10) [Oct 31 20:21:04] DEBUG[26602]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 31 20:21:04] DEBUG[26602]: chan_sip.c:3184 update_call_counter: Call to peer '7777' removed from call limit 1 [Oct 31 20:21:04] DEBUG[26602]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777 [Oct 31 20:21:04] DEBUG[26602]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777-08218cb8 [Oct 31 20:21:04] DEBUG[26602]: rtp.c:1503 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Oct 31 20:21:04] DEBUG[26602]: app_dial.c:1691 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Oct 31 20:21:04] DEBUG[26602]: pbx.c:2407 __ast_pbx_run: Spawn extension (default,4308,1) exited non-zero on 'SIP/138-08214d48' == Spawn extension (default, 4308, 1) exited non-zero on 'SIP/138-08214d48' [Oct 31 20:21:04] DEBUG[26602]: channel.c:1545 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/138-08214d48' [Oct 31 20:21:04] DEBUG[26602]: channel.c:1762 ast_hangup: Hanging up channel 'SIP/138-08214d48' [Oct 31 20:21:04] DEBUG[26602]: chan_sip.c:3445 sip_hangup: Hangup call SIP/138-08214d48, SIP callid 39765d15-135b1f42-972f4a4b@192. 168.0.155) [Oct 31 20:21:04] DEBUG[26602]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 31 20:21:04] DEBUG[26602]: chan_sip.c:3184 update_call_counter: Call from user '138' removed from call limit 8 [Oct 31 20:21:04] DEBUG[26602]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 31 20:21:04] DEBUG[26602]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138-08214d48 [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:21:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:21:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:21:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:21:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:21:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 1 (Not in use) [Oct 31 20:21:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:21:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 Really destroying SIP dialog '4f12ac744a9747dd686af9d609ddaacd@192.168.0.10' Method: BYE [Oct 31 20:21:04] DEBUG[26610]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 31 20:21:04] DEBUG[26611]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 31 20:21:04] DEBUG[26612]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '1' (Not in use) but we don't care b ecause they're not a member of any queue. [Oct 31 20:21:04] DEBUG[26602]: cdr_addon_mysql.c:211 mysql_log: cdr_mysql: inserting a CDR record. [Oct 31 20:21:04] DEBUG[26602]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,s rc,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2007-10-31 20:20:43','\"Nasir Qureshi\" <302>','302','4308','default', 'SIP/138-08214d48','SIP/7777-08218cb8','Dial','SIP/7777',21,11,'ANSWERE D',3,'','') [Oct 31 20:21:04] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 39765d15-135b1f42-972f4a4b@192.168.0.155 Their Tag E214980-B1305BF1 Our tag: as53b62593 [Oct 31 20:21:04] DEBUG[26551]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '39765d15-135b1f42-972f4a4b@192.168.0.155' of Request 102: Match Not Found Really destroying SIP dialog '39765d15-135b1f42-972f4a4b@192.168.0.155' Method: ACK mit2*CLI> [Oct 31 20:21:05] DEBUG[26535]: chan_iax2.c:8320 iax2_do_register: Allocate call number [Oct 31 20:21:05] DEBUG[26535]: chan_iax2.c:8326 iax2_do_register: Registration created on call 2 mit2*CLI> sip show subscriptions Peer User Call ID Extension Last state Type Mailbox 0 active SIP subscriptions mit2*CLI> core show hints mit2*CLI> -= Registered Asterisk Dial Plan Hints =- 4302@default : SIP/138 State:Idle Watchers 0 4308@default : SIP/7777 State:Idle Watchers 0 ---------------- - 2 hints registered ############################## Calling from SIP/7777 to SIP/138 [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: bf5890ab-9a250460-b5d7e151@192.168.0.155 Their Tag CE243F4E-3933FFE7 Our tag: as1976e3cf [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:4454 sip_alloc: Allocating new SIP dialog for 2021571179@192.168.0.26 - INVITE (With RTP) [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Oct 31 20:33:54] DEBUG[26551]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 2021571179@192.168.0.26 Their Tag 1374335209 Our t ag: as66ad7a68 [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '2021571179@192.168.0.26' of Response 1: Match Not Found [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 2021571179@192.168.0.26 Their Tag 1374335209 Our t ag: as66ad7a68 [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:5305 process_sdp: T38 state changed to 0 on channel [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:5385 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:13639 handle_request_invite: Checking SIP call limits for device 7777 [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:3210 update_call_counter: Call from user '7777' is 1 out of 1 [Oct 31 20:33:54] DEBUG[26551]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:3948 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:3949 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:3950 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Oct 31 20:33:54] DEBUG[26551]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:3951 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:3974 sip_new: This channel will not be able to handle video. [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:8144 build_route: build_route: Contact hop: [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:13718 handle_request_invite: SIP/7777-0821fb40: New call is still down.... Trying... [Oct 31 20:33:54] DEBUG[26551]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777-0821fb40 [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:33:54] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:33:54] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:33:54] DEBUG[26758]: pbx.c:1809 pbx_extension_helper: Launching 'Dial' -- Executing [4302@extensions:1] Dial("SIP/7777-0821fb40", "SIP/138") in new stack [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:15654 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:4454 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 31 20:33:54] DEBUG[26758]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3948 sip_new: *** Our native formats are 0x80004 (ulaw|h263) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3949 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3950 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Oct 31 20:33:54] DEBUG[26758]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3951 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3953 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3974 sip_new: This channel will not be able to handle video. [Oct 31 20:33:54] DEBUG[26758]: channel.c:3534 ast_channel_inherit_variables: Not copying variable STACK-extensions-4302-1. [Oct 31 20:33:54] DEBUG[26758]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 31 20:33:54] DEBUG[26758]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 31 20:33:54] DEBUG[26758]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 31 20:33:54] DEBUG[26758]: channel.c:3534 ast_channel_inherit_variables: Not copying variable SIPURI. [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:2953 sip_call: Outgoing Call for 138 [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:3210 update_call_counter: Call to peer '138' is 1 out of 8 [Oct 31 20:33:54] DEBUG[26758]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138 [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:33:54] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 6 (Ringing) [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:33:54] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:2968 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:6342 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:6343 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:6360 add_sdp: This call needs video offers, but there's no video support enabled! [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:6474 add_sdp: -- Done with adding codecs to SDP [Oct 31 20:33:54] DEBUG[26758]: channel.c:2547 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 ch an->timingfd=35) [Oct 31 20:33:54] DEBUG[26758]: chan_sip.c:6519 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h2 63) [Oct 31 20:33:54] DEBUG[26758]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! -- Called 138 [Oct 31 20:33:54] DEBUG[26759]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 31 20:33:54] DEBUG[26760]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '6' (Ringing) but we don't care beca use they're not a member of any queue. [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10 Thei r Tag Our tag: as0209cc33 [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '76a 8b9c2260f2c53754ff7295d2bb838@192.168.0.10' Request 102: Found [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:11818 handle_response_invite: SIP response 100 to standard invite [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10 Thei r Tag 585F3452-5DD1381B Our tag: as0209cc33 [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '76a 8b9c2260f2c53754ff7295d2bb838@192.168.0.10' Request 102: Found [Oct 31 20:33:54] DEBUG[26551]: chan_sip.c:11818 handle_response_invite: SIP response 180 to standard invite [Oct 31 20:33:54] DEBUG[26551]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138-08225ba0 -- SIP/138-08225ba0 is ringing [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:33:54] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 6 (Ringing) [Oct 31 20:33:54] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:33:54] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:33:54] DEBUG[26761]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '6' (Ringing) but we don't care beca use they're not a member of any queue. mit2*CLI> core show hints mit2*CLI> -= Registered Asterisk Dial Plan Hints =- 4302@extensions : SIP/138 State:Ringing Watchers 0 4308@extensions : SIP/7777 State:Idle Watchers 1 ---------------- - 2 hints registered [Oct 31 20:33:59] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: 76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10 T heir Tag 585F3452-5DD1381B Our tag: as0209cc33 [Oct 31 20:33:59] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: 2021571179@192.168.0.26 Their Tag 1374335209 Ou r tag: as690cae29 [Oct 31 20:33:59] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: bf5890ab-9a250460-b5d7e151@192.168.0.155 Their Tag CE243F4E-3933FFE7 Our tag: as1976e3cf [Oct 31 20:33:59] DEBUG[26551]: chan_sip.c:15145 sipsock_read: Invalid SIP message - rejected , no callid, len 423 [Oct 31 20:34:00] DEBUG[26543]: chan_iax2.c:8320 iax2_do_register: Allocate call number [Oct 31 20:34:00] DEBUG[26543]: chan_iax2.c:8326 iax2_do_register: Registration created on call 8 [Oct 31 20:34:00] DEBUG[26539]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 1575! mit2*CLI> sip show subscriptions Peer User Call ID Extension Last state Type Mailbox 192.168.0.155 138 bf5890ab-9a 4308@extensions Idle xpidf+xml 1 active SIP subscription ##################################### Call Answered: [Oct 31 20:34:02] DEBUG[26535]: chan_iax2.c:8320 iax2_do_register: Allocate call number [Oct 31 20:34:02] DEBUG[26535]: chan_iax2.c:8326 iax2_do_register: Registration created on call 4 [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10 Thei r Tag 585F3452-5DD1381B Our tag: as0209cc33 [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:2140 __sip_ack: Acked pending invite 102 [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10 ' of Request 102: Match Not Found [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:11818 handle_response_invite: SIP response 200 to standard invite [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:5305 process_sdp: T38 state changed to 0 on channel SIP/138-08225ba0 [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:5385 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:5392 process_sdp: We have an owner, now see if we need to change this call [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 31 20:34:04] DEBUG[26551]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138 [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:8144 build_route: build_route: Contact hop: [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 2 (In use) [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:04] DEBUG[26758]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138-08225ba0 -- SIP/138-08225ba0 answered SIP/7777-0821fb40 [Oct 31 20:34:04] DEBUG[26758]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777-0821fb40 [Oct 31 20:34:04] DEBUG[26758]: chan_sip.c:3602 sip_answer: SIP answering channel: SIP/7777-0821fb40 [Oct 31 20:34:04] DEBUG[26758]: chan_sip.c:6578 transmit_response_with_sdp: Setting framing from config on incoming call [Oct 31 20:34:04] DEBUG[26758]: chan_sip.c:6342 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Oct 31 20:34:04] DEBUG[26758]: chan_sip.c:6343 add_sdp: ** Our prefcodec: 0x0 (nothing) [Oct 31 20:34:04] DEBUG[26758]: chan_sip.c:6474 add_sdp: -- Done with adding codecs to SDP [Oct 31 20:34:04] DEBUG[26758]: channel.c:2547 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 ch an->timingfd=31) [Oct 31 20:34:04] DEBUG[26758]: chan_sip.c:6519 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Oct 31 20:34:04] DEBUG[26758]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 2 (In use) [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:34:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Oct 31 20:34:04] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:34:04] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:34:04] DEBUG[26762]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '2' (In use) but we don't care becau se they're not a member of any queue. [Oct 31 20:34:04] DEBUG[26763]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '2' (In use) but we don't care becau se they're not a member of any queue. [Oct 31 20:34:04] DEBUG[26764]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:4507 find_call: = No match Their Call ID: 76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10 T heir Tag 585F3452-5DD1381B Our tag: as0209cc33 [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 2021571179@192.168.0.26 Their Tag 1374335209 Our t ag: as690cae29 [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 31 20:34:04] DEBUG[26551]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '2021571179@192.168.0.26' of Response 2: Match Not Found [Oct 31 20:34:04] DEBUG[26758]: chan_sip.c:4236 sip_rtp_read: Oooh, format changed to 8 [Oct 31 20:34:04] DEBUG[26758]: channel.c:3024 set_format: Set channel SIP/7777-0821fb40 to read format ulaw [Oct 31 20:34:04] DEBUG[26758]: channel.c:3024 set_format: Set channel SIP/7777-0821fb40 to write format ulaw [Oct 31 20:34:04] DEBUG[26758]: rtp.c:2731 ast_rtp_write: Ooh, format changed from unknown to ulaw [Oct 31 20:34:04] DEBUG[26758]: rtp.c:2748 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Oct 31 20:34:04] DEBUG[26758]: rtp.c:2731 ast_rtp_write: Ooh, format changed from unknown to alaw [Oct 31 20:34:04] DEBUG[26758]: rtp.c:2748 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Oct 31 20:34:07] DEBUG[26758]: rtp.c:879 ast_rtcp_read: Got RTCP report of 80 bytes mit2*CLI> core show hints mit2*CLI> -= Registered Asterisk Dial Plan Hints =- 4302@extensions : SIP/138 State:InUse Watchers 0 4308@extensions : SIP/7777 State:Idle Watchers 1 ---------------- - 2 hints registered mit2*CLI> sip show subscriptions Peer User Call ID Extension Last state Type Mailbox 192.168.0.155 138 bf5890ab-9a 4308@extensions Idle xpidf+xml 1 active SIP subscription #################################### Call Ended: [Oct 31 20:34:12] DEBUG[26758]: rtp.c:879 ast_rtcp_read: Got RTCP report of 80 bytes [Oct 31 20:34:14] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10 Thei r Tag 585F3452-5DD1381B Our tag: as0209cc33 [Oct 31 20:34:14] DEBUG[26551]: chan_sip.c:14961 handle_request: **** Received BYE (8) - Command in SIP BYE [Oct 31 20:34:14] DEBUG[26551]: chan_sip.c:1646 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 76a8b9c2260f2c53754ff7295d2bb838@ 192.168.0.10 [Oct 31 20:34:14] DEBUG[26551]: chan_sip.c:14503 handle_request_bye: Received bye, issuing owner hangup [Oct 31 20:34:14] DEBUG[26758]: channel.c:4034 ast_generic_bridge: Didn't get a frame from channel: SIP/138-08225ba0 [Oct 31 20:34:14] DEBUG[26758]: channel.c:4358 ast_channel_bridge: Bridge stops bridging channels SIP/7777-0821fb40 and SIP/138-0822 5ba0 [Oct 31 20:34:14] DEBUG[26758]: channel.c:1762 ast_hangup: Hanging up channel 'SIP/138-08225ba0' [Oct 31 20:34:14] DEBUG[26758]: chan_sip.c:3445 sip_hangup: Hangup call SIP/138-08225ba0, SIP callid 76a8b9c2260f2c53754ff7295d2bb83 8@192.168.0.10) [Oct 31 20:34:14] DEBUG[26758]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 31 20:34:14] DEBUG[26758]: chan_sip.c:3184 update_call_counter: Call to peer '138' removed from call limit 8 [Oct 31 20:34:14] DEBUG[26758]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138 [Oct 31 20:34:14] DEBUG[26758]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/138-08225ba0 [Oct 31 20:34:14] DEBUG[26758]: rtp.c:1503 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Oct 31 20:34:14] DEBUG[26758]: app_dial.c:1691 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Oct 31 20:34:14] DEBUG[26758]: pbx.c:2407 __ast_pbx_run: Spawn extension (extensions,4302,1) exited non-zero on 'SIP/7777-0821fb40' == Spawn extension (extensions, 4302, 1) exited non-zero on 'SIP/7777-0821fb40' [Oct 31 20:34:14] DEBUG[26758]: channel.c:1545 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/7777-0821fb40' [Oct 31 20:34:14] DEBUG[26758]: channel.c:1762 ast_hangup: Hanging up channel 'SIP/7777-0821fb40' [Oct 31 20:34:14] DEBUG[26758]: chan_sip.c:3445 sip_hangup: Hangup call SIP/7777-0821fb40, SIP callid 2021571179@192.168.0.26) [Oct 31 20:34:14] DEBUG[26758]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 31 20:34:14] DEBUG[26758]: chan_sip.c:3184 update_call_counter: Call from user '7777' removed from call limit 1 [Oct 31 20:34:14] DEBUG[26758]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 31 20:34:14] DEBUG[26758]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on d evice/channel SIP/7777-0821fb40 Really destroying SIP dialog '76a8b9c2260f2c53754ff7295d2bb838@192.168.0.10' Method: BYE [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:14] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 1 (Not in use) [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:14] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:14] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/138 - state 1 (Not in use) [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 138 [Oct 31 20:34:14] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 138 [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:34:14] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:287 do_state_change: Changing state for SIP/7777 - state 1 (Not in use) [Oct 31 20:34:14] DEBUG[26528]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7777 [Oct 31 20:34:14] DEBUG[26528]: chan_sip.c:15588 sip_devicestate: Checking device state for peer 7777 [Oct 31 20:34:14] DEBUG[26758]: cdr_addon_mysql.c:211 mysql_log: cdr_mysql: inserting a CDR record. [Oct 31 20:34:14] DEBUG[26758]: cdr_addon_mysql.c:228 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,s rc,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2007-10-31 20:33:54','\"A.R. Nasir Qureshi\" <302>','302','4302','extensions', 'SIP/7777-0821fb40','SIP/138-08225ba0','Dial','SIP/138',20,10,' ANSWERED',3,'','') [Oct 31 20:34:14] DEBUG[26766]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '1' (Not in use) but we don't care b ecause they're not a member of any queue. [Oct 31 20:34:14] DEBUG[26767]: app_queue.c:566 changethread: Device 'SIP/138' changed to state '1' (Not in use) but we don't care b ecause they're not a member of any queue. [Oct 31 20:34:14] DEBUG[26768]: app_queue.c:566 changethread: Device 'SIP/7777' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 31 20:34:14] DEBUG[26551]: chan_sip.c:4507 find_call: = Found Their Call ID: 2021571179@192.168.0.26 Their Tag 1374335209 Our t ag: as690cae29 [Oct 31 20:34:14] DEBUG[26551]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '2021571179@192.168.0.26' of Request 102: Matc h Not Found Really destroying SIP dialog '2021571179@192.168.0.26' Method: ACK mit2*CLI> core show hints mit2*CLI> -= Registered Asterisk Dial Plan Hints =- 4302@extensions : SIP/138 State:Idle Watchers 0 4308@extensions : SIP/7777 State:Idle Watchers 1 ---------------- - 2 hints registered mit2*CLI> sip show subscriptions Peer User Call ID Extension Last state Type Mailbox 192.168.0.155 138 bf5890ab-9a 4308@extensions Idle xpidf+xml 1 active SIP subscription