[Jan 15 15:12:00] DEBUG[14824]: manager.c:2107 process_message: Manager received command 'Login' == Parsing '/etc/asterisk/manager.conf': [Jan 15 15:12:00] DEBUG[14824]: config.c:889 config_text_file_load: Parsing /etc/asterisk/manager.conf Found [Jan 15 15:12:00] DEBUG[14824]: manager.c:2107 process_message: Manager received command 'Command' [Jan 15 15:12:00] DEBUG[14824]: manager.c:2107 process_message: Manager received command 'Logoff' [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1597945069@xxx.xxx.xxx.xxx6 Their Tag 5f3eb4ed Our tag: as6b017480 [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1688809215@xxx.xxx.xxx.xxx6 Their Tag 64a92eff Our tag: as2a718f78 [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 323764829@xxx.xxx.xxx.xxx6 Their Tag 134c425d Our tag: as2c777583 [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18 - INVITE (With RTP) [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:13834 handle_request_invite: Checking SIP call limits for device [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:3993 sip_new: *** Our native formats are 0x8 (alaw) [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:3994 sip_new: *** Joint capabilities are 0x8 (alaw) [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:3995 sip_new: *** Our capabilities are 0x108 (alaw|g729) [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:3996 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:4019 sip_new: This channel will not be able to handle video. [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:8212 build_route: build_route: Record-Route hop: [Jan 15 15:12:03] DEBUG[14793]: chan_sip.c:13913 handle_request_invite: SIP/xxx.xxx.xxx.xxx18-092b4e50: New call is still down.... Trying... [Jan 15 15:12:03] DEBUG[14793]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xxx.xxx.xxx.xxx18-092b4e50 [Jan 15 15:12:03] DEBUG[14776]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - xxx.xxx.xxx.xxx18 [Jan 15 15:12:03] DEBUG[14776]: chan_sip.c:15788 sip_devicestate: Checking device state for peer xxx.xxx.xxx.xxx18 [Jan 15 15:12:03] DEBUG[14776]: devicestate.c:287 do_state_change: Changing state for SIP/xxx.xxx.xxx.xxx18 - state 2 (In use) [Jan 15 15:12:03] DEBUG[14800]: app_queue.c:589 handle_statechange: Device 'SIP/xxx.xxx.xxx.xxx18' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 15 15:12:03] DEBUG[14825]: pbx.c:1831 pbx_extension_helper: Launching 'AGI' -- Executing [800098420@from-internal:1] AGI("SIP/xxx.xxx.xxx.xxx18-092b4e50", "agi://127.0.0.1/enswitch?stype=internal") in new stack [Jan 15 15:12:03] DEBUG[14825]: res_agi.c:232 launch_netscript: Wow, connected! -- Channel will hangup at 2008-01-16 14:12:03 UTC. -- AGI Script Executing Application: (SetMusicOnHold) Options: (default) -- Channel will hangup at 2008-01-16 14:12:03 UTC. -- AGI Script Executing Application: (SetCallerPres) Options: (allowed_not_screened) [Jan 15 15:12:03] DEBUG[14825]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx18-092b4e50 to write format gsm -- Playing '/opt/enswitch/current/sounds/local/it_IT/enter-pin-hash' (escape_digits=1234567890*#) (sample_offset 0) [Jan 15 15:12:03] DEBUG[14825]: chan_sip.c:6657 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 15 15:12:03] DEBUG[14825]: chan_sip.c:6421 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Jan 15 15:12:03] DEBUG[14825]: chan_sip.c:6422 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jan 15 15:12:03] DEBUG[14825]: chan_sip.c:6553 add_sdp: -- Done with adding codecs to SDP [Jan 15 15:12:03] DEBUG[14825]: channel.c:2579 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 15 15:12:03] DEBUG[14825]: chan_sip.c:6598 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Jan 15 15:12:03] DEBUG[14825]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to alaw [Jan 15 15:12:03] DEBUG[14825]: rtp.c:2776 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Jan 15 15:12:04] DEBUG[14825]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 15 15:12:05] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18 Their Tag 384E2404-8F5 Our tag: as4e02ca0b [Jan 15 15:12:05] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1597945069@xxx.xxx.xxx.xxx6 Their Tag 5f3eb4ed Our tag: as6b017480 [Jan 15 15:12:05] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1688809215@xxx.xxx.xxx.xxx6 Their Tag 64a92eff Our tag: as2a718f78 [Jan 15 15:12:05] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 323764829@xxx.xxx.xxx.xxx6 Their Tag 134c425d Our tag: as2c777583 [Jan 15 15:12:05] DEBUG[14793]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 1563597925@xxx.xxx.xxx.xxx6 - OPTIONS (No RTP) [Jan 15 15:12:05] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 15 15:12:06] NOTICE[14825]: rtp.c:787 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: xxx.xxx.xxx.xxx18 [Jan 15 15:12:06] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:06] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:06] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:06] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:06] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:06] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:06] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:06] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:06] DEBUG[14825]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx18-092b4e50 to write format alaw [Jan 15 15:12:06] DEBUG[14825]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx18-092b4e50 to write format gsm -- Playing '/opt/enswitch/current/sounds/local/it_IT/silence/1' (language 'it_IT') [Jan 15 15:12:06] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx18-092b4e50 to write format alaw [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14793]: chan_sip.c:2091 __sip_autodestruct: Auto destroying SIP dialog '323764829@xxx.xxx.xxx.xxx6' [Jan 15 15:12:07] DEBUG[14793]: chan_sip.c:3282 sip_destroy: Destroying SIP dialog 323764829@xxx.xxx.xxx.xxx6 Really destroying SIP dialog '323764829@xxx.xxx.xxx.xxx6' Method: OPTIONS [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:07] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:08] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 56 (8), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 56 (8), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:12:09] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:10] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:12:11] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:12:11] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:11] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:12:11] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:12:11] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:12:11] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:12:11] DEBUG[14825]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at xxx.xxx.xxx.xxx18 [Jan 15 15:12:11] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:12:11] DEBUG[14825]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx18-092b4e50 to write format gsm -- Playing '/opt/enswitch/current/sounds/local/it_IT/enter-pin-hash' (escape_digits=1234567890*#) (sample_offset 0) [Jan 15 15:12:11] DEBUG[14825]: rtp.c:2629 ast_rtp_raw_write: Difference is 31296, ms is 3932 [Jan 15 15:12:11] DEBUG[14825]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:12:12] DEBUG[14825]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 15 15:12:15] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1563597925@xxx.xxx.xxx.xxx6 Their Tag 5d329c65 Our tag: as67b8969b [Jan 15 15:12:15] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18 Their Tag 384E2404-8F5 Our tag: as4e02ca0b [Jan 15 15:12:15] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1597945069@xxx.xxx.xxx.xxx6 Their Tag 5f3eb4ed Our tag: as6b017480 [Jan 15 15:12:15] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1688809215@xxx.xxx.xxx.xxx6 Their Tag 64a92eff Our tag: as2a718f78 [Jan 15 15:12:15] DEBUG[14793]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 601066036@xxx.xxx.xxx.xxx6 - OPTIONS (No RTP) [Jan 15 15:12:15] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 15 15:12:17] DEBUG[14793]: chan_sip.c:2091 __sip_autodestruct: Auto destroying SIP dialog '1688809215@xxx.xxx.xxx.xxx6' [Jan 15 15:12:17] DEBUG[14793]: chan_sip.c:3282 sip_destroy: Destroying SIP dialog 1688809215@xxx.xxx.xxx.xxx6 Really destroying SIP dialog '1688809215@xxx.xxx.xxx.xxx6' Method: OPTIONS [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 601066036@xxx.xxx.xxx.xxx6 Their Tag 23d38a34 Our tag: as3b60860d [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1563597925@xxx.xxx.xxx.xxx6 Their Tag 5d329c65 Our tag: as67b8969b [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:4562 find_call: = Found Their Call ID: ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18 Their Tag 384E2404-8F5 Our tag: as4e02ca0b [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:1652 sip_alreadygone: Setting SIP_ALREADYGONE on dialog ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18 [Jan 15 15:12:18] DEBUG[14825]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx18-092b4e50 to write format alaw [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 601066036@xxx.xxx.xxx.xxx6 Their Tag 23d38a34 Our tag: as3b60860d [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1563597925@xxx.xxx.xxx.xxx6 Their Tag 5d329c65 Our tag: as67b8969b [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:4562 find_call: = Found Their Call ID: ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18 Their Tag 384E2404-8F5 Our tag: as4e02ca0b [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 15 15:12:18] DEBUG[14793]: chan_sip.c:2170 __sip_ack: Stopping retransmission on 'ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18' of Response 101: Match Not Found [Jan 15 15:12:18] DEBUG[14825]: res_agi.c:1860 run_agi: SIP/xxx.xxx.xxx.xxx18-092b4e50 hungup [Jan 15 15:12:18] DEBUG[14825]: pbx.c:2427 __ast_pbx_run: Spawn extension (from-internal,800098420,1) exited non-zero on 'SIP/xxx.xxx.xxx.xxx18-092b4e50' == Spawn extension (from-internal, 800098420, 1) exited non-zero on 'SIP/xxx.xxx.xxx.xxx18-092b4e50' [Jan 15 15:12:18] DEBUG[14825]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/xxx.xxx.xxx.xxx18-092b4e50' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1831 pbx_extension_helper: Launching 'DeadAGI' -- Executing [h@from-internal:1] DeadAGI("SIP/xxx.xxx.xxx.xxx18-092b4e50", "agi://127.0.0.1/end") in new stack [Jan 15 15:12:18] DEBUG[14825]: res_agi.c:232 launch_netscript: Wow, connected! [Jan 15 15:12:18] DEBUG[14825]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/xxx.xxx.xxx.xxx18-092b4e50' -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jan 15 15:12:18] DEBUG[14825]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/xxx.xxx.xxx.xxx18-092b4e50' [Jan 15 15:12:18] DEBUG[14825]: chan_sip.c:3485 sip_hangup: Hangup call SIP/xxx.xxx.xxx.xxx18-092b4e50, SIP callid ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18) [Jan 15 15:12:18] DEBUG[14825]: chan_sip.c:3508 sip_hangup: Hanging up channel in state Ring (not UP) [Jan 15 15:12:18] DEBUG[14825]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xxx.xxx.xxx.xxx18-092b4e50 [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0793079808' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0793079808' [Jan 15 15:12:18] DEBUG[14776]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - xxx.xxx.xxx.xxx18 [Jan 15 15:12:18] DEBUG[14776]: chan_sip.c:15788 sip_devicestate: Checking device state for peer xxx.xxx.xxx.xxx18 [Jan 15 15:12:18] DEBUG[14776]: devicestate.c:287 do_state_change: Changing state for SIP/xxx.xxx.xxx.xxx18 - state 1 (Not in use) [Jan 15 15:12:18] DEBUG[14800]: app_queue.c:589 handle_statechange: Device 'SIP/xxx.xxx.xxx.xxx18' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '800098420' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'from-internal' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SIP/xxx.xxx.xxx.xxx18-092b4e50' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SetCallerPres' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'allowed_not_screened' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2008-01-15 15:12:03' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2008-01-15 15:12:18' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '15' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1200406323.2' [Jan 15 15:12:18] DEBUG[14825]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' Really destroying SIP dialog 'ADC90CC3-C2AA11DC-9172CC73-1113E0FD@xxx.xxx.xxx.xxx18' Method: ACK