]1;Asterisk]2;Asterisk Console on 'MyPBX' (pid 2799)*CLI> [Jun 12 12:28:05] -- Accepting AUTHENTICATED call from 192.168.2.140: > requested format = ulaw, > requested prefs = (ulaw|alaw), > actual format = ulaw, > host prefs = (ulaw|alaw|gsm), > priority = mine [Jun 12 12:28:05] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [Jun 12 12:28:05] -- Executing [s@iax-default:1] Goto("IAX2/XXXXXXXXXX-2", "open|s|1") in new stack [Jun 12 12:28:05] -- Goto (open,s,1) [Jun 12 12:28:05] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Wait' [Jun 12 12:28:05] -- Executing [s@open:1] Wait("IAX2/XXXXXXXXXX-2", "1") in new stack [Jun 12 12:28:05] DEBUG[2814]: chan_iax2.c:6775 socket_process: Ooh, voice format changed to 4 [Jun 12 12:28:05] DEBUG[2814]: channel.c:2966 set_format: Set channel IAX2/XXXXXXXXXX-2 to read format ulaw [Jun 12 12:28:06] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Answer' [Jun 12 12:28:06] -- Executing [s@open:2] Answer("IAX2/XXXXXXXXXX-2", "") in new stack [Jun 12 12:28:06] DEBUG[2821]: chan_iax2.c:3242 iax2_answer: Answering IAX2 call [Jun 12 12:28:06] DEBUG[2821]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/XXXXXXXXXX-2 [Jun 12 12:28:06] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:28:06] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - XXXXXXXXXX [Jun 12 12:28:06] DEBUG[2803]: chan_iax2.c:9840 iax2_devicestate: Checking device state for device XXXXXXXXXX [Jun 12 12:28:06] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for IAX2/XXXXXXXXXX - state 4 (Invalid) [Jun 12 12:28:06] -- Executing [s@open:3] Set("IAX2/XXXXXXXXXX-2", "TIMEOUT(digit)=1") in new stack [Jun 12 12:28:06] -- Digit timeout set to 1 [Jun 12 12:28:06] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:28:06] -- Executing [s@open:4] Set("IAX2/XXXXXXXXXX-2", "TIMEOUT(response)=10") in new stack [Jun 12 12:28:06] -- Response timeout set to 10 [Jun 12 12:28:06] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:28:06] -- Executing [s@open:5] Set("IAX2/XXXXXXXXXX-2", "Repetition=3") in new stack [Jun 12 12:28:06] DEBUG[2822]: app_queue.c:546 changethread: Device 'IAX2/XXXXXXXXXX' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 12 12:28:06] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Wait' [Jun 12 12:28:06] -- Executing [s@open:6] Wait("IAX2/XXXXXXXXXX-2", "2") in new stack [Jun 12 12:28:08] DEBUG[2821]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '2' [Jun 12 12:28:08] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:28:08] -- Executing [s@open:7] Set("IAX2/XXXXXXXXXX-2", "Repetition=2") in new stack [Jun 12 12:28:08] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp' [Jun 12 12:28:08] -- Executing [s@open:8] NoOp("IAX2/XXXXXXXXXX-2", "2") in new stack [Jun 12 12:28:08] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'BackGround' [Jun 12 12:28:08] -- Executing [s@open:9] BackGround("IAX2/XXXXXXXXXX-2", "mysounds/aa_1") in new stack [Jun 12 12:28:08] DEBUG[2821]: channel.c:2966 set_format: Set channel IAX2/XXXXXXXXXX-2 to write format gsm [Jun 12 12:28:08] DEBUG[2821]: channel.c:2051 ast_settimeout: Scheduling timer at 160 sample intervals [Jun 12 12:28:08] -- Playing 'mysounds/aa_1' (language 'fr') [Jun 12 12:28:08] DEBUG[2821]: chan_iax2.c:3617 find_tpeer: Created trunk peer for '192.168.2.140:4569' [Jun 12 12:28:08] DEBUG[2821]: chan_iax2.c:3645 iax2_trunk_queue: Expanded trunk '192.168.2.140:4569' to 6400 bytes [Jun 12 12:28:11] DEBUG[2821]: channel.c:2051 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 12 12:28:11] DEBUG[2821]: channel.c:2966 set_format: Set channel IAX2/XXXXXXXXXX-2 to write format ulaw [Jun 12 12:28:11] DEBUG[2821]: pbx.c:2392 __ast_pbx_run: Oooh, got something to jump out with ('8')! [Jun 12 12:28:11] == CDR updated on IAX2/XXXXXXXXXX-2 [Jun 12 12:28:11] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [Jun 12 12:28:11] -- Executing [8@open:1] Goto("IAX2/XXXXXXXXXX-2", "open|4200|1") in new stack [Jun 12 12:28:11] -- Goto (open,4200,1) [Jun 12 12:28:11] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [Jun 12 12:28:11] -- Executing [4200@open:1] Goto("IAX2/XXXXXXXXXX-2", "sip-internal|4200|1") in new stack [Jun 12 12:28:11] -- Goto (sip-internal,4200,1) [Jun 12 12:28:11] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Macro' [Jun 12 12:28:11] -- Executing [4200@sip-internal:1] Macro("IAX2/XXXXXXXXXX-2", "stdexten|4200|SIP/4200") in new stack [Jun 12 12:28:11] DEBUG[2821]: pbx.c:1809 pbx_extension_helper: Launching 'Dial' [Jun 12 12:28:11] -- Executing [s@macro-stdexten:1] Dial("IAX2/XXXXXXXXXX-2", "SIP/4200|20") in new stack [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:15512 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:4365 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:7705 reg_source_db: SIP Seeding peer from astdb: '4200' at 4200@192.168.2.27:5060 for 3600 [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:2619 do_setnat: Setting NAT on RTP to Off [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3857 sip_new: *** Our native formats are 0x4 (ulaw) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3858 sip_new: *** Joint capabilities are 0x0 (nothing) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3859 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3860 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3862 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3883 sip_new: This channel will not be able to handle video. [Jun 12 12:28:11] -- Message count requested for mailbox 2400@MyPBX but voicemail not loaded. [Jun 12 12:28:11] DEBUG[2819]: chan_sip.c:4365 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Jun 12 12:28:11] DEBUG[2821]: rtp.c:1576 ast_rtp_make_compatible: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable ARG2. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable ARG1. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-sip-internal-4200-1. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-4200-1. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-8-1. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-9. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-8. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable Repetition. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-7. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-6. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-5. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-4. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-3. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-2. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-1. [Jun 12 12:28:11] DEBUG[2821]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-iax-default-s-1. [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:2875 sip_call: Outgoing Call for 4200 [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3051 update_call_counter: Updating call counter for outgoing call [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:3125 update_call_counter: Call to peer '4200' is 1 out of 2 [Jun 12 12:28:11] DEBUG[2821]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200 [Jun 12 12:28:11] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:28:11] DEBUG[2803]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:28:11] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 6 (Ringing) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:2890 sip_call: Our T38 capability (0), joint T38 capability (0) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:6250 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:6251 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:6382 add_sdp: -- Done with adding codecs to SDP [Jun 12 12:28:11] DEBUG[2821]: channel.c:2489 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Jun 12 12:28:11] DEBUG[2821]: chan_sip.c:6427 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Jun 12 12:28:11] -- Called 4200 [Jun 12 12:28:11] DEBUG[2823]: app_queue.c:546 changethread: Device 'SIP/4200' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 12 12:28:11] DEBUG[2819]: chan_sip.c:4418 find_call: = Found Their Call ID: 71e5b5693c7d47a2559c166f18653812@192.168.2.150 Their Tag Our tag: as2284585d [Jun 12 12:28:11] DEBUG[2819]: chan_sip.c:2133 __sip_ack: Stopping retransmission on '71e5b5693c7d47a2559c166f18653812@192.168.2.150' of Request 102: Match Not Found [Jun 12 12:28:11] Really destroying SIP dialog '71e5b5693c7d47a2559c166f18653812@192.168.2.150' Method: NOTIFY [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:1897 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #4)) [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:4418 find_call: = Found Their Call ID: 2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150 Their Tag Our tag: as73e15348 [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:2175 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150' Request 102: Found [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:11712 handle_response_invite: SIP response 100 to standard invite [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:4418 find_call: = Found Their Call ID: 2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150 Their Tag DB361C4E-4972B6D5 Our tag: as73e15348 [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:2175 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150' Request 102: Found [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:11712 handle_response_invite: SIP response 100 to standard invite [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:4418 find_call: = Found Their Call ID: 2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150 Their Tag DB361C4E-4972B6D5 Our tag: as73e15348 [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:2175 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150' Request 102: Found [Jun 12 12:28:12] DEBUG[2819]: chan_sip.c:11712 handle_response_invite: SIP response 180 to standard invite [Jun 12 12:28:12] DEBUG[2819]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200-08222800 [Jun 12 12:28:12] -- SIP/4200-08222800 is ringing [Jun 12 12:28:12] DEBUG[2821]: rtp.c:1486 ast_rtp_early_bridge: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:28:12] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:28:12] DEBUG[2803]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:28:12] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 6 (Ringing) [Jun 12 12:28:12] DEBUG[2824]: app_queue.c:546 changethread: Device 'SIP/4200' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:4418 find_call: = Found Their Call ID: 2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150 Their Tag DB361C4E-4972B6D5 Our tag: as73e15348 [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:2115 __sip_ack: Acked pending invite 102 [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:2133 __sip_ack: Stopping retransmission on '2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150' of Request 102: Match Not Found [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:11712 handle_response_invite: SIP response 200 to standard invite [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:5216 process_sdp: T38 state changed to 0 on channel SIP/4200-08222800 [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:5296 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:5303 process_sdp: We have an owner, now see if we need to change this call [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:3051 update_call_counter: Updating call counter for outgoing call [Jun 12 12:28:15] DEBUG[2819]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200 [Jun 12 12:28:15] DEBUG[2819]: chan_sip.c:8054 build_route: build_route: Contact hop: [Jun 12 12:28:15] DEBUG[2821]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200-08222800 [Jun 12 12:28:15] -- SIP/4200-08222800 answered IAX2/XXXXXXXXXX-2 [Jun 12 12:28:15] DEBUG[2821]: rtp.c:1486 ast_rtp_early_bridge: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:28:15] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:28:15] DEBUG[2803]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:28:15] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 2 (In use) [Jun 12 12:28:15] DEBUG[2825]: app_queue.c:546 changethread: Device 'SIP/4200' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 12 12:28:15] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:28:15] DEBUG[2803]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:28:15] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 2 (In use) [Jun 12 12:28:15] DEBUG[2826]: app_queue.c:546 changethread: Device 'SIP/4200' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jun 12 12:28:15] DEBUG[2821]: rtp.c:2719 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jun 12 12:28:15] DEBUG[2821]: rtp.c:2736 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jun 12 12:28:21] DEBUG[2821]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:28:21] Internal RTCP NTP clock skew detected: lsr=1210378789, now=1210443820, dlsr=65500 (0:999ms), diff=469 [Jun 12 12:28:25] WARNING[2818]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32773) of type 6 (subclass 11) due to frame of type 6 (subclass 2) already in process [Jun 12 12:28:25] DEBUG[2811]: chan_iax2.c:6634 socket_process: Packet arrived out of order (expecting 8, got 9) (frametype = 6, subclass = 3) [Jun 12 12:28:25] DEBUG[2812]: chan_iax2.c:6725 socket_process: Received iseqno 8 not within window 9->10 [Jun 12 12:28:25] WARNING[2818]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32773) of type 6 (subclass 3) due to frame of type 6 (subclass 11) already in process [Jun 12 12:28:25] DEBUG[2816]: chan_iax2.c:6634 socket_process: Packet arrived out of order (expecting 9, got 10) (frametype = 6, subclass = 12) [Jun 12 12:28:25] WARNING[2818]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32773) of type 6 (subclass 12) due to frame of type 6 (subclass 3) already in process [Jun 12 12:28:25] DEBUG[2807]: chan_iax2.c:6725 socket_process: Received iseqno 10 not within window 11->12 [Jun 12 12:28:31] DEBUG[2821]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:28:31] Internal RTCP NTP clock skew detected: lsr=1211034112, now=1211099182, dlsr=65500 (0:999ms), diff=430 [Jun 12 12:28:41] DEBUG[2821]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:28:41] Internal RTCP NTP clock skew detected: lsr=1211689435, now=1211754556, dlsr=65500 (0:999ms), diff=379 [Jun 12 12:28:45] DEBUG[2815]: chan_iax2.c:6725 socket_process: Received iseqno 16 not within window 17->17 [Jun 12 12:28:48] DEBUG[2813]: chan_iax2.c:7858 iax2_do_register: Allocate call number [Jun 12 12:28:48] DEBUG[2813]: chan_iax2.c:7864 iax2_do_register: Registration created on call 3 [Jun 12 12:28:51] DEBUG[2821]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:28:51] Internal RTCP NTP clock skew detected: lsr=1212344757, now=1212409931, dlsr=65500 (0:999ms), diff=326 [Jun 12 12:28:54] DEBUG[2821]: rtp.c:2589 ast_rtp_raw_write: Difference is 960, ms is 140 [Jun 12 12:28:55] DEBUG[2821]: rtp.c:2589 ast_rtp_raw_write: Difference is 960, ms is 140 [Jun 12 12:28:55] DEBUG[2821]: rtp.c:2589 ast_rtp_raw_write: Difference is 960, ms is 140 [Jun 12 12:29:00] DEBUG[2819]: chan_sip.c:4418 find_call: = Found Their Call ID: 2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150 Their Tag DB361C4E-4972B6D5 Our tag: as73e15348 [Jun 12 12:29:00] DEBUG[2819]: chan_sip.c:14826 handle_request: **** Received BYE (8) - Command in SIP BYE [Jun 12 12:29:00] DEBUG[2819]: chan_sip.c:1640 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150 [Jun 12 12:29:00] DEBUG[2819]: chan_sip.c:14371 handle_request_bye: Received bye, issuing owner hangup [Jun 12 12:29:00] DEBUG[2821]: channel.c:3923 ast_generic_bridge: Didn't get a frame from channel: SIP/4200-08222800 [Jun 12 12:29:00] DEBUG[2821]: channel.c:4241 ast_channel_bridge: Bridge stops bridging channels IAX2/XXXXXXXXXX-2 and SIP/4200-08222800 [Jun 12 12:29:00] DEBUG[2821]: channel.c:1747 ast_hangup: Hanging up channel 'SIP/4200-08222800' [Jun 12 12:29:00] DEBUG[2821]: chan_sip.c:3360 sip_hangup: Hangup call SIP/4200-08222800, SIP callid 2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150) [Jun 12 12:29:00] DEBUG[2821]: chan_sip.c:3051 update_call_counter: Updating call counter for outgoing call [Jun 12 12:29:00] DEBUG[2821]: chan_sip.c:3099 update_call_counter: Call to peer '4200' removed from call limit 2 [Jun 12 12:29:00] DEBUG[2821]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200 [Jun 12 12:29:00] DEBUG[2821]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200-08222800 [Jun 12 12:29:00] DEBUG[2821]: rtp.c:1486 ast_rtp_early_bridge: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:29:00] DEBUG[2821]: app_dial.c:1686 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jun 12 12:29:00] DEBUG[2821]: app_macro.c:329 _macro_exec: Spawn extension (macro-stdexten,s,1) exited non-zero on 'IAX2/XXXXXXXXXX-2' in macro 'stdexten' [Jun 12 12:29:00] DEBUG[2821]: pbx.c:2407 __ast_pbx_run: Spawn extension (macro-stdexten,s,1) exited non-zero on 'IAX2/XXXXXXXXXX-2' [Jun 12 12:29:00] == Spawn extension (macro-stdexten, s, 1) exited non-zero on 'IAX2/XXXXXXXXXX-2' [Jun 12 12:29:00] DEBUG[2821]: channel.c:1747 ast_hangup: Hanging up channel 'IAX2/XXXXXXXXXX-2' [Jun 12 12:29:00] DEBUG[2821]: chan_iax2.c:2993 iax2_hangup: We're hanging up IAX2/XXXXXXXXXX-2 now... [Jun 12 12:29:00] -- Hungup 'IAX2/XXXXXXXXXX-2' [Jun 12 12:29:00] DEBUG[2821]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/XXXXXXXXXX-2 [Jun 12 12:29:00] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:29:00] DEBUG[2803]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:29:00] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 1 (Not in use) [Jun 12 12:29:00] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:29:00] DEBUG[2803]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:29:00] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 1 (Not in use) [Jun 12 12:29:00] DEBUG[2803]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - XXXXXXXXXX [Jun 12 12:29:00] DEBUG[2803]: chan_iax2.c:9840 iax2_devicestate: Checking device state for device XXXXXXXXXX [Jun 12 12:29:00] DEBUG[2803]: devicestate.c:287 do_state_change: Changing state for IAX2/XXXXXXXXXX - state 4 (Invalid) [Jun 12 12:29:00] DEBUG[2827]: app_queue.c:546 changethread: Device 'SIP/4200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 12:29:00] DEBUG[2828]: app_queue.c:546 changethread: Device 'SIP/4200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 12:29:00] DEBUG[2829]: app_queue.c:546 changethread: Device 'IAX2/XXXXXXXXXX' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jun 12 12:29:01] Really destroying SIP dialog '2e75d6225c0a47c04b1f89ed4b75f2d4@192.168.2.150' Method: BYE [Jun 12 12:29:06] DEBUG[2818]: chan_iax2.c:6060 timing_read: Dropping unused iax2 trunk peer '192.168.2.140:4569' stop now [Jun 12 12:29:12] Beginning asterisk shutdown.... [Jun 12 12:29:12] Executing last minute cleanups [Jun 12 12:29:12] == Destroying musiconhold processes [Jun 12 12:29:12] Asterisk cleanly ending (0). [Jun 12 12:29:12] DEBUG[2799]: asterisk.c:1278 quit_handler: Asterisk ending (0).