]1;Asterisk]2;Asterisk Console on 'MyPBX' (pid 2757)*CLI> [Jun 12 12:24:10] -- 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:24:10] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [Jun 12 12:24:10] -- Executing [s@iax-default:1] Goto("IAX2/XXXXXXXXXX-2", "open|s|1") in new stack [Jun 12 12:24:10] -- Goto (open,s,1) [Jun 12 12:24:10] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Wait' [Jun 12 12:24:10] -- Executing [s@open:1] Wait("IAX2/XXXXXXXXXX-2", "1") in new stack [Jun 12 12:24:10] DEBUG[2772]: chan_iax2.c:6775 socket_process: Ooh, voice format changed to 4 [Jun 12 12:24:10] DEBUG[2772]: channel.c:2966 set_format: Set channel IAX2/XXXXXXXXXX-2 to read format ulaw [Jun 12 12:24:11] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Answer' [Jun 12 12:24:11] -- Executing [s@open:2] Answer("IAX2/XXXXXXXXXX-2", "") in new stack [Jun 12 12:24:11] DEBUG[2779]: chan_iax2.c:3242 iax2_answer: Answering IAX2 call [Jun 12 12:24:11] DEBUG[2779]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/XXXXXXXXXX-2 [Jun 12 12:24:11] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:24:11] -- Executing [s@open:3] Set("IAX2/XXXXXXXXXX-2", "TIMEOUT(digit)=1") in new stack [Jun 12 12:24:11] -- Digit timeout set to 1 [Jun 12 12:24:11] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:24:11] -- Executing [s@open:4] Set("IAX2/XXXXXXXXXX-2", "TIMEOUT(response)=10") in new stack [Jun 12 12:24:11] -- Response timeout set to 10 [Jun 12 12:24:11] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:24:11] -- Executing [s@open:5] Set("IAX2/XXXXXXXXXX-2", "Repetition=3") in new stack [Jun 12 12:24:11] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Wait' [Jun 12 12:24:11] -- Executing [s@open:6] Wait("IAX2/XXXXXXXXXX-2", "2") in new stack [Jun 12 12:24:11] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - XXXXXXXXXX [Jun 12 12:24:11] DEBUG[2761]: chan_iax2.c:9840 iax2_devicestate: Checking device state for device XXXXXXXXXX [Jun 12 12:24:11] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for IAX2/XXXXXXXXXX - state 4 (Invalid) [Jun 12 12:24:11] DEBUG[2780]: 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:24:14] DEBUG[2779]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '2' [Jun 12 12:24:14] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Set' [Jun 12 12:24:14] -- Executing [s@open:7] Set("IAX2/XXXXXXXXXX-2", "Repetition=2") in new stack [Jun 12 12:24:14] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp' [Jun 12 12:24:14] -- Executing [s@open:8] NoOp("IAX2/XXXXXXXXXX-2", "2") in new stack [Jun 12 12:24:14] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'BackGround' [Jun 12 12:24:14] -- Executing [s@open:9] BackGround("IAX2/XXXXXXXXXX-2", "mysounds/aa_1") in new stack [Jun 12 12:24:14] DEBUG[2779]: channel.c:2966 set_format: Set channel IAX2/XXXXXXXXXX-2 to write format gsm [Jun 12 12:24:14] DEBUG[2779]: channel.c:2051 ast_settimeout: Scheduling timer at 160 sample intervals [Jun 12 12:24:14] -- Playing 'mysounds/aa_1' (language 'fr') [Jun 12 12:24:14] DEBUG[2779]: chan_iax2.c:3617 find_tpeer: Created trunk peer for '192.168.2.140:4569' [Jun 12 12:24:14] DEBUG[2779]: chan_iax2.c:3645 iax2_trunk_queue: Expanded trunk '192.168.2.140:4569' to 6400 bytes [Jun 12 12:24:18] DEBUG[2779]: channel.c:2051 ast_settimeout: Scheduling timer at 0 sample intervals [Jun 12 12:24:18] DEBUG[2779]: channel.c:2966 set_format: Set channel IAX2/XXXXXXXXXX-2 to write format ulaw [Jun 12 12:24:18] DEBUG[2779]: pbx.c:2392 __ast_pbx_run: Oooh, got something to jump out with ('8')! [Jun 12 12:24:18] == CDR updated on IAX2/XXXXXXXXXX-2 [Jun 12 12:24:18] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [Jun 12 12:24:18] -- Executing [8@open:1] Goto("IAX2/XXXXXXXXXX-2", "open|4200|1") in new stack [Jun 12 12:24:18] -- Goto (open,4200,1) [Jun 12 12:24:18] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [Jun 12 12:24:18] -- Executing [4200@open:1] Goto("IAX2/XXXXXXXXXX-2", "sip-internal|4200|1") in new stack [Jun 12 12:24:18] -- Goto (sip-internal,4200,1) [Jun 12 12:24:18] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Macro' [Jun 12 12:24:18] -- Executing [4200@sip-internal:1] Macro("IAX2/XXXXXXXXXX-2", "stdexten|4200|SIP/4200") in new stack [Jun 12 12:24:18] DEBUG[2779]: pbx.c:1809 pbx_extension_helper: Launching 'Dial' [Jun 12 12:24:18] -- Executing [s@macro-stdexten:1] Dial("IAX2/XXXXXXXXXX-2", "SIP/4200|20") in new stack [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:15512 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:4365 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 12 12:24:18] DEBUG[2779]: 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:24:18] DEBUG[2779]: chan_sip.c:2619 do_setnat: Setting NAT on RTP to Off [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3857 sip_new: *** Our native formats are 0x4 (ulaw) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3858 sip_new: *** Joint capabilities are 0x0 (nothing) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3859 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3860 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3862 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3883 sip_new: This channel will not be able to handle video. [Jun 12 12:24:18] DEBUG[2779]: rtp.c:1576 ast_rtp_make_compatible: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable ARG2. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable ARG1. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-sip-internal-4200-1. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-4200-1. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-8-1. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-9. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-8. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable Repetition. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-7. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-6. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-5. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-4. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-3. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-2. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-open-s-1. [Jun 12 12:24:18] DEBUG[2779]: channel.c:3432 ast_channel_inherit_variables: Not copying variable STACK-iax-default-s-1. [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:2875 sip_call: Outgoing Call for 4200 [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3051 update_call_counter: Updating call counter for outgoing call [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:3125 update_call_counter: Call to peer '4200' is 1 out of 2 [Jun 12 12:24:18] DEBUG[2779]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200 [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:2890 sip_call: Our T38 capability (0), joint T38 capability (0) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:6250 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:6251 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jun 12 12:24:18] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:6382 add_sdp: -- Done with adding codecs to SDP [Jun 12 12:24:18] DEBUG[2761]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:24:18] DEBUG[2779]: channel.c:2489 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=24) [Jun 12 12:24:18] DEBUG[2779]: chan_sip.c:6427 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:2448 inboxcount: Mailbox is set to 2400@MyPBX [Jun 12 12:24:18] -- Called 4200 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: jdoe not found in vmstates [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8742 get_vm_state_by_mailbox: Mailbox set to 2400 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8764 get_vm_state_by_mailbox: 2400 not found in vmstates [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: jdoe not found in vmstates [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8742 get_vm_state_by_mailbox: Mailbox set to 2400 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8764 get_vm_state_by_mailbox: 2400 not found in vmstates [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:2519 inboxcount: Adding new vmstate for jdoe [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:2528 inboxcount: Copied jdoe to jdoe [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8807 vmstate_insert: Inserting vm_state for user:jdoe, mailbox 2400 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:4663 init_mailstream: vm_state user is:jdoe [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:4666 init_mailstream: mailstream not set. [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8552 mm_log: IMAP Info: Trying IP address [127.0.0.1] [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8552 mm_log: IMAP Info: Dovecot ready. [Jun 12 12:24:18] WARNING[2777]: app_voicemail.c:8556 mm_log: IMAP Warning: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8576 mm_login: Entering callback mm_login [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8461 mm_exists: Entering EXISTS callback for message 2 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: asterisk not found in vmstates [Jun 12 12:24:18] WARNING[2777]: app_voicemail.c:8872 set_update: User asterisk mailbox not found for update. [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8501 mm_list: Delimiter set to / and mailbox {localhost}Junk E-mail [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8503 mm_list: no inferiors [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8509 mm_list: unmarked [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8501 mm_list: Delimiter set to / and mailbox {localhost}INBOX [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8503 mm_list: no inferiors [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8509 mm_list: unmarked [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:4692 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=jdoe}INBOX, box:0 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8552 mm_log: IMAP Info: Reusing connection to localhost/user="jdoe" [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8461 mm_exists: Entering EXISTS callback for message 2 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: asterisk not found in vmstates [Jun 12 12:24:18] WARNING[2777]: app_voicemail.c:8872 set_update: User asterisk mailbox not found for update. [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 1 as message 0. Interactive set to 0 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 2 as message 1. Interactive set to 0 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 1 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 2 [Jun 12 12:24:18] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:18] DEBUG[2777]: chan_sip.c:4365 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Jun 12 12:24:18] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 6 (Ringing) [Jun 12 12:24:18] DEBUG[2783]: 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:24:18] DEBUG[2777]: chan_sip.c:4418 find_call: = No match Their Call ID: 5708dc514873dbec75bf4c2a4aae61f8@192.168.2.150 Their Tag Our tag: as5c8da79c [Jun 12 12:24:18] DEBUG[2777]: chan_sip.c:4418 find_call: = Found Their Call ID: 75ea573977744bf12b5a33f26d5fecdb@192.168.2.150 Their Tag Our tag: as5fbd1648 [Jun 12 12:24:18] DEBUG[2777]: chan_sip.c:2175 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '75ea573977744bf12b5a33f26d5fecdb@192.168.2.150' Request 102: Found [Jun 12 12:24:18] DEBUG[2777]: chan_sip.c:11712 handle_response_invite: SIP response 100 to standard invite [Jun 12 12:24:18] DEBUG[2777]: chan_sip.c:4418 find_call: = Found Their Call ID: 5708dc514873dbec75bf4c2a4aae61f8@192.168.2.150 Their Tag Our tag: as5c8da79c [Jun 12 12:24:18] DEBUG[2777]: chan_sip.c:2133 __sip_ack: Stopping retransmission on '5708dc514873dbec75bf4c2a4aae61f8@192.168.2.150' of Request 102: Match Not Found [Jun 12 12:24:18] Really destroying SIP dialog '5708dc514873dbec75bf4c2a4aae61f8@192.168.2.150' Method: NOTIFY [Jun 12 12:24:19] DEBUG[2777]: chan_sip.c:4418 find_call: = Found Their Call ID: 75ea573977744bf12b5a33f26d5fecdb@192.168.2.150 Their Tag BE06844D-3587E624 Our tag: as5fbd1648 [Jun 12 12:24:19] DEBUG[2777]: chan_sip.c:2175 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '75ea573977744bf12b5a33f26d5fecdb@192.168.2.150' Request 102: Found [Jun 12 12:24:19] DEBUG[2777]: chan_sip.c:11712 handle_response_invite: SIP response 180 to standard invite [Jun 12 12:24:19] DEBUG[2777]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200-08223bb8 [Jun 12 12:24:19] -- SIP/4200-08223bb8 is ringing [Jun 12 12:24:19] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:24:19] DEBUG[2761]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:24:19] DEBUG[2779]: rtp.c:1486 ast_rtp_early_bridge: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:24:19] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 6 (Ringing) [Jun 12 12:24:19] DEBUG[2785]: 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:24:24] DEBUG[2776]: chan_iax2.c:6060 timing_read: Dropping unused iax2 trunk peer '192.168.2.140:4569' [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:4418 find_call: = Found Their Call ID: 75ea573977744bf12b5a33f26d5fecdb@192.168.2.150 Their Tag BE06844D-3587E624 Our tag: as5fbd1648 [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:2115 __sip_ack: Acked pending invite 102 [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:2133 __sip_ack: Stopping retransmission on '75ea573977744bf12b5a33f26d5fecdb@192.168.2.150' of Request 102: Match Not Found [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:11712 handle_response_invite: SIP response 200 to standard invite [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:5216 process_sdp: T38 state changed to 0 on channel SIP/4200-08223bb8 [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:5296 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:5303 process_sdp: We have an owner, now see if we need to change this call [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:3051 update_call_counter: Updating call counter for outgoing call [Jun 12 12:24:25] DEBUG[2777]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200 [Jun 12 12:24:25] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:24:25] DEBUG[2761]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:24:25] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 2 (In use) [Jun 12 12:24:25] DEBUG[2777]: chan_sip.c:8054 build_route: build_route: Contact hop: [Jun 12 12:24:25] DEBUG[2779]: rtp.c:2719 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jun 12 12:24:25] DEBUG[2786]: 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:24:25] DEBUG[2779]: rtp.c:2736 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jun 12 12:24:25] DEBUG[2779]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200-08223bb8 [Jun 12 12:24:25] -- SIP/4200-08223bb8 answered IAX2/XXXXXXXXXX-2 [Jun 12 12:24:25] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:24:25] DEBUG[2761]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:24:25] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 2 (In use) [Jun 12 12:24:25] DEBUG[2787]: 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:24:25] DEBUG[2779]: rtp.c:1486 ast_rtp_early_bridge: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:24:25] DEBUG[2779]: chan_iax2.c:3617 find_tpeer: Created trunk peer for '192.168.2.140:4569' [Jun 12 12:24:25] DEBUG[2779]: chan_iax2.c:3645 iax2_trunk_queue: Expanded trunk '192.168.2.140:4569' to 6400 bytes [Jun 12 12:24:27] DEBUG[2779]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:2448 inboxcount: Mailbox is set to 2400@MyPBX [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: jdoe not found in vmstates [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8742 get_vm_state_by_mailbox: Mailbox set to 2400 [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8747 get_vm_state_by_mailbox: comparing mailbox 2400 (i=1) to vmstate mailbox 2400 (i=0) [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8764 get_vm_state_by_mailbox: 2400 not found in vmstates [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:4663 init_mailstream: vm_state user is:jdoe [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:4692 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=jdoe}INBOX, box:0 [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8552 mm_log: IMAP Info: Reusing connection to localhost/user="jdoe" [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8461 mm_exists: Entering EXISTS callback for message 2 [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: asterisk not found in vmstates [Jun 12 12:24:29] WARNING[2777]: app_voicemail.c:8872 set_update: User asterisk mailbox not found for update. [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 1 as message 0. Interactive set to 0 [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 2 as message 1. Interactive set to 0 [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 1 [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 2 [Jun 12 12:24:29] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:30] WARNING[2776]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32771) of type 6 (subclass 11) due to frame of type 6 (subclass 2) already in process [Jun 12 12:24:30] DEBUG[2769]: chan_iax2.c:7465 socket_process: Received VNAK: resending outstanding frames [Jun 12 12:24:30] WARNING[2776]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32771) of type 6 (subclass 4) due to frame of type 6 (subclass 18) already in process [Jun 12 12:24:30] DEBUG[2771]: chan_iax2.c:7465 socket_process: Received VNAK: resending outstanding frames [Jun 12 12:24:30] DEBUG[2773]: chan_iax2.c:6634 socket_process: Packet arrived out of order (expecting 8, got 9) (frametype = 6, subclass = 12) [Jun 12 12:24:30] WARNING[2776]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32771) of type 6 (subclass 3) due to frame of type 6 (subclass 12) already in process [Jun 12 12:24:30] DEBUG[2768]: chan_iax2.c:6725 socket_process: Received iseqno 8 not within window 11->11 [Jun 12 12:24:30] WARNING[2776]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32771) of type 6 (subclass 3) due to frame of type 6 (subclass 11) already in process [Jun 12 12:24:30] DEBUG[2766]: chan_iax2.c:6725 socket_process: Received iseqno 10 not within window 11->12 [Jun 12 12:24:37] DEBUG[2779]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:24:37] Internal RTCP NTP clock skew detected: lsr=1195574521, now=1195704484, dlsr=131000 (1:998ms), diff=1037 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:2448 inboxcount: Mailbox is set to 2400@MyPBX [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: jdoe not found in vmstates [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8742 get_vm_state_by_mailbox: Mailbox set to 2400 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8747 get_vm_state_by_mailbox: comparing mailbox 2400 (i=1) to vmstate mailbox 2400 (i=0) [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8764 get_vm_state_by_mailbox: 2400 not found in vmstates [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:4663 init_mailstream: vm_state user is:jdoe [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:4692 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=jdoe}INBOX, box:0 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8552 mm_log: IMAP Info: Reusing connection to localhost/user="jdoe" [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8461 mm_exists: Entering EXISTS callback for message 2 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: asterisk not found in vmstates [Jun 12 12:24:40] WARNING[2777]: app_voicemail.c:8872 set_update: User asterisk mailbox not found for update. [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 1 as message 0. Interactive set to 0 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 2 as message 1. Interactive set to 0 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 1 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 2 [Jun 12 12:24:40] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:47] DEBUG[2779]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:24:47] Internal RTCP NTP clock skew detected: lsr=1196229849, now=1196359859, dlsr=131000 (1:998ms), diff=990 [Jun 12 12:24:50] WARNING[2776]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32771) of type 6 (subclass 11) due to frame of type 6 (subclass 2) already in process [Jun 12 12:24:50] DEBUG[2768]: chan_iax2.c:6634 socket_process: Packet arrived out of order (expecting 14, got 15) (frametype = 6, subclass = 3) [Jun 12 12:24:50] WARNING[2776]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32771) of type 6 (subclass 12) due to frame of type 6 (subclass 3) already in process [Jun 12 12:24:50] DEBUG[2766]: chan_iax2.c:6725 socket_process: Received iseqno 14 not within window 15->17 [Jun 12 12:24:50] WARNING[2776]: chan_iax2.c:6322 socket_read: Dropping frame from 192.168.2.140 (callno 32771) of type 6 (subclass 12) due to frame of type 6 (subclass 11) already in process [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:2448 inboxcount: Mailbox is set to 2400@MyPBX [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: jdoe not found in vmstates [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8742 get_vm_state_by_mailbox: Mailbox set to 2400 [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8747 get_vm_state_by_mailbox: comparing mailbox 2400 (i=1) to vmstate mailbox 2400 (i=0) [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8764 get_vm_state_by_mailbox: 2400 not found in vmstates [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:4663 init_mailstream: vm_state user is:jdoe [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:4692 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=jdoe}INBOX, box:0 [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8552 mm_log: IMAP Info: Reusing connection to localhost/user="jdoe" [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8461 mm_exists: Entering EXISTS callback for message 2 [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: asterisk not found in vmstates [Jun 12 12:24:51] WARNING[2777]: app_voicemail.c:8872 set_update: User asterisk mailbox not found for update. [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 1 as message 0. Interactive set to 0 [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 2 as message 1. Interactive set to 0 [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 1 [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 2 [Jun 12 12:24:51] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:24:52] DEBUG[2769]: chan_iax2.c:7858 iax2_do_register: Allocate call number [Jun 12 12:24:52] DEBUG[2769]: chan_iax2.c:7864 iax2_do_register: Registration created on call 3 [Jun 12 12:24:57] DEBUG[2779]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Jun 12 12:24:57] Internal RTCP NTP clock skew detected: lsr=1196885167, now=1197015230, dlsr=131000 (1:998ms), diff=937 [Jun 12 12:25:00] DEBUG[2777]: chan_sip.c:4418 find_call: = Found Their Call ID: 75ea573977744bf12b5a33f26d5fecdb@192.168.2.150 Their Tag BE06844D-3587E624 Our tag: as5fbd1648 [Jun 12 12:25:00] DEBUG[2777]: chan_sip.c:14826 handle_request: **** Received BYE (8) - Command in SIP BYE [Jun 12 12:25:00] DEBUG[2777]: chan_sip.c:1640 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 75ea573977744bf12b5a33f26d5fecdb@192.168.2.150 [Jun 12 12:25:00] DEBUG[2777]: chan_sip.c:14371 handle_request_bye: Received bye, issuing owner hangup [Jun 12 12:25:00] DEBUG[2779]: channel.c:3923 ast_generic_bridge: Didn't get a frame from channel: SIP/4200-08223bb8 [Jun 12 12:25:00] DEBUG[2779]: channel.c:4241 ast_channel_bridge: Bridge stops bridging channels IAX2/XXXXXXXXXX-2 and SIP/4200-08223bb8 [Jun 12 12:25:00] DEBUG[2779]: channel.c:1747 ast_hangup: Hanging up channel 'SIP/4200-08223bb8' [Jun 12 12:25:00] DEBUG[2779]: chan_sip.c:3360 sip_hangup: Hangup call SIP/4200-08223bb8, SIP callid 75ea573977744bf12b5a33f26d5fecdb@192.168.2.150) [Jun 12 12:25:00] DEBUG[2779]: chan_sip.c:3051 update_call_counter: Updating call counter for outgoing call [Jun 12 12:25:00] DEBUG[2779]: chan_sip.c:3099 update_call_counter: Call to peer '4200' removed from call limit 2 [Jun 12 12:25:00] DEBUG[2779]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200 [Jun 12 12:25:00] DEBUG[2779]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4200-08223bb8 [Jun 12 12:25:00] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:25:00] DEBUG[2761]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:25:00] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 1 (Not in use) [Jun 12 12:25:00] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4200 [Jun 12 12:25:00] DEBUG[2761]: chan_sip.c:15446 sip_devicestate: Checking device state for peer 4200 [Jun 12 12:25:00] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for SIP/4200 - state 1 (Not in use) [Jun 12 12:25:00] DEBUG[2779]: rtp.c:1486 ast_rtp_early_bridge: Channel 'IAX2/XXXXXXXXXX-2' has no RTP, not doing anything [Jun 12 12:25:00] DEBUG[2788]: 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:25:00] DEBUG[2779]: app_dial.c:1686 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jun 12 12:25:00] DEBUG[2789]: 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:25:00] DEBUG[2779]: 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:25:00] DEBUG[2779]: pbx.c:2407 __ast_pbx_run: Spawn extension (macro-stdexten,s,1) exited non-zero on 'IAX2/XXXXXXXXXX-2' [Jun 12 12:25:00] == Spawn extension (macro-stdexten, s, 1) exited non-zero on 'IAX2/XXXXXXXXXX-2' [Jun 12 12:25:00] DEBUG[2779]: channel.c:1747 ast_hangup: Hanging up channel 'IAX2/XXXXXXXXXX-2' [Jun 12 12:25:00] DEBUG[2779]: chan_iax2.c:2993 iax2_hangup: We're hanging up IAX2/XXXXXXXXXX-2 now... [Jun 12 12:25:00] -- Hungup 'IAX2/XXXXXXXXXX-2' [Jun 12 12:25:00] DEBUG[2779]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/XXXXXXXXXX-2 [Jun 12 12:25:00] DEBUG[2761]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - XXXXXXXXXX [Jun 12 12:25:00] DEBUG[2761]: chan_iax2.c:9840 iax2_devicestate: Checking device state for device XXXXXXXXXX [Jun 12 12:25:00] DEBUG[2761]: devicestate.c:287 do_state_change: Changing state for IAX2/XXXXXXXXXX - state 4 (Invalid) [Jun 12 12:25:00] DEBUG[2790]: 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:25:01] Really destroying SIP dialog '75ea573977744bf12b5a33f26d5fecdb@192.168.2.150' Method: BYE [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:2448 inboxcount: Mailbox is set to 2400@MyPBX [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: jdoe not found in vmstates [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8742 get_vm_state_by_mailbox: Mailbox set to 2400 [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8747 get_vm_state_by_mailbox: comparing mailbox 2400 (i=1) to vmstate mailbox 2400 (i=0) [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8764 get_vm_state_by_mailbox: 2400 not found in vmstates [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:4663 init_mailstream: vm_state user is:jdoe [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:4692 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=jdoe}INBOX, box:0 [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8552 mm_log: IMAP Info: Reusing connection to localhost/user="jdoe" [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8461 mm_exists: Entering EXISTS callback for message 2 [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8732 get_vm_state_by_imapuser: asterisk not found in vmstates [Jun 12 12:25:02] WARNING[2777]: app_voicemail.c:8872 set_update: User asterisk mailbox not found for update. [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 1 as message 0. Interactive set to 0 [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8259 mm_searched: saving mailbox message number 2 as message 1. Interactive set to 0 [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 1 [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8481 mm_flags: Entering FLAGS callback for message 2 [Jun 12 12:25:02] DEBUG[2777]: app_voicemail.c:8868 set_update: User jdoe mailbox set for update. sti[Jun 12 12:25:06] DEBUG[2776]: chan_iax2.c:6060 timing_read: Dropping unused iax2 trunk peer '192.168.2.140:4569' stop No such command 'stop' (type 'help' for help) *CLI> exit No such command 'exit' (type 'help' for help) *CLI> qstop now [Jun 12 12:25:12] Beginning asterisk shutdown.... [Jun 12 12:25:12] Executing last minute cleanups [Jun 12 12:25:12] == Destroying musiconhold processes [Jun 12 12:25:12] Asterisk cleanly ending (0). [Jun 12 12:25:12] DEBUG[2757]: asterisk.c:1278 quit_handler: Asterisk ending (0).