[Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1071657838@xxx.xxx.xxx.xxx6 Their Tag 3fe0336e Our tag: as2aa7649d [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 454664832@xxx.xxx.xxx.xxx6 Their Tag 1b19a280 Our tag: as022664c1 [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 271141914@xxx.xxx.xxx.xxx6 Their Tag 10294c1a Our tag: as588ca6f9 [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 574782483@xxx.xxx.xxx.xxx6 - OPTIONS (No RTP) [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 574782483@xxx.xxx.xxx.xxx6 Their Tag 22427c13 Our tag: as416dae1d [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1071657838@xxx.xxx.xxx.xxx6 Their Tag 3fe0336e Our tag: as2aa7649d [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 454664832@xxx.xxx.xxx.xxx6 Their Tag 1b19a280 Our tag: as022664c1 [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 271141914@xxx.xxx.xxx.xxx6 Their Tag 10294c1a Our tag: as588ca6f9 [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx - INVITE (With RTP) [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to On [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x8 (alaw) [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:13834 handle_request_invite: Checking SIP call limits for device [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:3993 sip_new: *** Our native formats are 0x8 (alaw) [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:3994 sip_new: *** Joint capabilities are 0x8 (alaw) [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:3995 sip_new: *** Our capabilities are 0x108 (alaw|g729) [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:3996 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:4019 sip_new: This channel will not be able to handle video. [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:8212 build_route: build_route: Record-Route hop: [Jan 15 15:24:26] DEBUG[14793]: chan_sip.c:13913 handle_request_invite: SIP/xxx.xxx.xxx.xxx-092b0598: New call is still down.... Trying... [Jan 15 15:24:26] DEBUG[14793]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xxx.xxx.xxx.xxx-092b0598 [Jan 15 15:24:26] DEBUG[14776]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - xxx.xxx.xxx.xxx [Jan 15 15:24:26] DEBUG[14776]: chan_sip.c:15788 sip_devicestate: Checking device state for peer xxx.xxx.xxx.xxx [Jan 15 15:24:26] DEBUG[14776]: channel.c:1086 channel_find_locked: Avoiding initial deadlock for channel '0x92b46a8' [Jan 15 15:24:26] DEBUG[14888]: pbx.c:1831 pbx_extension_helper: Launching 'AGI' -- Executing [800098421@from-internal:1] AGI("SIP/xxx.xxx.xxx.xxx-092b0598", "agi://127.0.0.1/enswitch?stype=internal") in new stack [Jan 15 15:24:26] DEBUG[14776]: devicestate.c:287 do_state_change: Changing state for SIP/xxx.xxx.xxx.xxx - state 2 (In use) [Jan 15 15:24:26] DEBUG[14800]: app_queue.c:589 handle_statechange: Device 'SIP/xxx.xxx.xxx.xxx' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 15 15:24:26] DEBUG[14888]: res_agi.c:232 launch_netscript: Wow, connected! -- Channel will hangup at 2008-01-16 14:24:26 UTC. agi://127.0.0.1/enswitch?stype=internal: Resolving type '', number '800098421'. agi://127.0.0.1/enswitch?stype=internal: Customer 18 has 86400 inbound seconds available. -- AGI Script Executing Application: (SetMusicOnHold) Options: (default) agi://127.0.0.1/enswitch?stype=internal: Resolving type 'cardlogin', number ''. agi://127.0.0.1/enswitch?stype=internal: Writing entry to active table for 1200407066.10, external:3939366266 - cardlogin:. -- Channel will hangup at 2008-01-16 14:24:26 UTC. -- AGI Script Executing Application: (SetCallerPres) Options: (allowed_not_screened) [Jan 15 15:24:26] DEBUG[14888]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx-092b0598 to write format gsm -- Playing '/opt/enswitch/current/sounds/local/it_IT/enter-pin-hash' (escape_digits=1234567890*#) (sample_offset 0) [Jan 15 15:24:26] DEBUG[14888]: chan_sip.c:6657 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 15 15:24:26] DEBUG[14888]: chan_sip.c:6421 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Jan 15 15:24:26] DEBUG[14888]: chan_sip.c:6422 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jan 15 15:24:26] DEBUG[14888]: chan_sip.c:6553 add_sdp: -- Done with adding codecs to SDP [Jan 15 15:24:26] DEBUG[14888]: channel.c:2579 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 15 15:24:26] DEBUG[14888]: chan_sip.c:6598 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Jan 15 15:24:26] DEBUG[14888]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to alaw [Jan 15 15:24:26] DEBUG[14888]: rtp.c:2776 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Jan 15 15:24:27] DEBUG[14793]: chan_sip.c:2091 __sip_autodestruct: Auto destroying SIP dialog '271141914@xxx.xxx.xxx.xxx6' [Jan 15 15:24:27] DEBUG[14793]: chan_sip.c:3282 sip_destroy: Destroying SIP dialog 271141914@xxx.xxx.xxx.xxx6 Really destroying SIP dialog '271141914@xxx.xxx.xxx.xxx6' Method: OPTIONS [Jan 15 15:24:30] DEBUG[14888]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 15 15:24:32] DEBUG[14888]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 15 15:24:33] NOTICE[14888]: 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.xxx [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx [Jan 15 15:24:33] DEBUG[14888]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx-092b0598 to write format alaw [Jan 15 15:24:33] DEBUG[14888]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx-092b0598 to write format gsm -- Playing '/opt/enswitch/current/sounds/local/it_IT/silence/1' (language 'it_IT') [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:33] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:34] DEBUG[14888]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx-092b0598 to write format alaw [Jan 15 15:24:34] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:34] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx [Jan 15 15:24:34] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:34] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx Their Tag 38597C4C-A82 Our tag: as1c1dafdc [Jan 15 15:24:35] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 574782483@xxx.xxx.xxx.xxx6 Their Tag 22427c13 Our tag: as416dae1d [Jan 15 15:24:35] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1071657838@xxx.xxx.xxx.xxx6 Their Tag 3fe0336e Our tag: as2aa7649d [Jan 15 15:24:35] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 454664832@xxx.xxx.xxx.xxx6 Their Tag 1b19a280 Our tag: as022664c1 [Jan 15 15:24:35] DEBUG[14793]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 1278191593@xxx.xxx.xxx.xxx6 - OPTIONS (No RTP) [Jan 15 15:24:35] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 55 (7), at xxx.xxx.xxx.xxx [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:35] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000007 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:36] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at xxx.xxx.xxx.xxx [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14793]: chan_sip.c:2091 __sip_autodestruct: Auto destroying SIP dialog '454664832@xxx.xxx.xxx.xxx6' [Jan 15 15:24:37] DEBUG[14793]: chan_sip.c:3282 sip_destroy: Destroying SIP dialog 454664832@xxx.xxx.xxx.xxx6 Really destroying SIP dialog '454664832@xxx.xxx.xxx.xxx6' Method: OPTIONS [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at xxx.xxx.xxx.xxx [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:37] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx [Jan 15 15:24:38] DEBUG[14888]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at xxx.xxx.xxx.xxx [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:38] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:39] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 56 (8), at xxx.xxx.xxx.xxx [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:40] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 56 (8), at xxx.xxx.xxx.xxx [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:879 ast_rtcp_read: Got RTCP report of 108 bytes [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:41] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at xxx.xxx.xxx.xxx [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at xxx.xxx.xxx.xxx [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:42] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at xxx.xxx.xxx.xxx [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at xxx.xxx.xxx.xxx [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:43] DEBUG[14888]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx-092b0598 to write format gsm -- Playing '/opt/enswitch/current/sounds/local/it_IT/enter-destination-hash' (escape_digits=1234567890*#) (sample_offset 0) [Jan 15 15:24:43] DEBUG[14888]: rtp.c:2629 ast_rtp_raw_write: Difference is 71728, ms is 8986 [Jan 15 15:24:43] DEBUG[14888]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Jan 15 15:24:45] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1278191593@xxx.xxx.xxx.xxx6 Their Tag 4c2fa7e9 Our tag: as122c97c9 [Jan 15 15:24:45] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx Their Tag 38597C4C-A82 Our tag: as1c1dafdc [Jan 15 15:24:45] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 574782483@xxx.xxx.xxx.xxx6 Their Tag 22427c13 Our tag: as416dae1d [Jan 15 15:24:45] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1071657838@xxx.xxx.xxx.xxx6 Their Tag 3fe0336e Our tag: as2aa7649d [Jan 15 15:24:45] DEBUG[14793]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 1743596742@xxx.xxx.xxx.xxx6 - OPTIONS (No RTP) [Jan 15 15:24:45] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Jan 15 15:24:46] DEBUG[14888]: rtp.c:879 ast_rtcp_read: Got RTCP report of 132 bytes [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1743596742@xxx.xxx.xxx.xxx6 Their Tag 67ed2cc6 Our tag: as2d726245 [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1278191593@xxx.xxx.xxx.xxx6 Their Tag 4c2fa7e9 Our tag: as122c97c9 [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = Found Their Call ID: 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx Their Tag 38597C4C-A82 Our tag: as1c1dafdc [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:1652 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx [Jan 15 15:24:47] DEBUG[14888]: channel.c:3069 set_format: Set channel SIP/xxx.xxx.xxx.xxx-092b0598 to write format alaw [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1743596742@xxx.xxx.xxx.xxx6 Their Tag 67ed2cc6 Our tag: as2d726245 [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1278191593@xxx.xxx.xxx.xxx6 Their Tag 4c2fa7e9 Our tag: as122c97c9 [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = Found Their Call ID: 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx Their Tag 38597C4C-A82 Our tag: as1c1dafdc [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:15347 sipsock_read: Failed to grab owner channel lock, trying again. (SIP call 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx) [Jan 15 15:24:47] DEBUG[14888]: res_agi.c:1860 run_agi: SIP/xxx.xxx.xxx.xxx-092b0598 hungup [Jan 15 15:24:47] DEBUG[14888]: pbx.c:2427 __ast_pbx_run: Spawn extension (from-internal,800098421,1) exited non-zero on 'SIP/xxx.xxx.xxx.xxx-092b0598' == Spawn extension (from-internal, 800098421, 1) exited non-zero on 'SIP/xxx.xxx.xxx.xxx-092b0598' [Jan 15 15:24:47] DEBUG[14888]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/xxx.xxx.xxx.xxx-092b0598' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1831 pbx_extension_helper: Launching 'DeadAGI' -- Executing [h@from-internal:1] DeadAGI("SIP/xxx.xxx.xxx.xxx-092b0598", "agi://127.0.0.1/end") in new stack [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1743596742@xxx.xxx.xxx.xxx6 Their Tag 67ed2cc6 Our tag: as2d726245 [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = No match Their Call ID: 1278191593@xxx.xxx.xxx.xxx6 Their Tag 4c2fa7e9 Our tag: as122c97c9 [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:4562 find_call: = Found Their Call ID: 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx Their Tag 38597C4C-A82 Our tag: as1c1dafdc [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:15154 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx' of Response 101: Match Not Found [Jan 15 15:24:47] DEBUG[14888]: res_agi.c:232 launch_netscript: Wow, connected! [Jan 15 15:24:47] DEBUG[14888]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/xxx.xxx.xxx.xxx-092b0598' -- AGI Script agi://127.0.0.1/end completed, returning 0 [Jan 15 15:24:47] DEBUG[14888]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/xxx.xxx.xxx.xxx-092b0598' [Jan 15 15:24:47] DEBUG[14888]: chan_sip.c:3485 sip_hangup: Hangup call SIP/xxx.xxx.xxx.xxx-092b0598, SIP callid 68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx) [Jan 15 15:24:47] DEBUG[14888]: chan_sip.c:3508 sip_hangup: Hanging up channel in state Ring (not UP) [Jan 15 15:24:47] DEBUG[14888]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xxx.xxx.xxx.xxx-092b0598 [Jan 15 15:24:47] DEBUG[14776]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - xxx.xxx.xxx.xxx [Jan 15 15:24:47] DEBUG[14776]: chan_sip.c:15788 sip_devicestate: Checking device state for peer xxx.xxx.xxx.xxx [Jan 15 15:24:47] DEBUG[14776]: devicestate.c:287 do_state_change: Changing state for SIP/xxx.xxx.xxx.xxx - state 1 (Not in use) [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '3939366266' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '3939366266' [Jan 15 15:24:47] DEBUG[14800]: app_queue.c:589 handle_statechange: Device 'SIP/xxx.xxx.xxx.xxx' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '800098421' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'from-internal' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SIP/xxx.xxx.xxx.xxx-092b0598' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'SetCallerPres' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'allowed_not_screened' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2008-01-15 15:24:26' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '2008-01-15 15:24:47' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '21' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '0' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '1200407066.10' [Jan 15 15:24:47] DEBUG[14888]: pbx.c:1680 pbx_substitute_variables_helper_full: Function result is '' Really destroying SIP dialog '68F1D240-C2AC11DC-91AECC73-1113E0FD@xxx.xxx.xxx.xxx' Method: ACK [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:2091 __sip_autodestruct: Auto destroying SIP dialog '1071657838@xxx.xxx.xxx.xxx6' [Jan 15 15:24:47] DEBUG[14793]: chan_sip.c:3282 sip_destroy: Destroying SIP dialog 1071657838@xxx.xxx.xxx.xxx6 Really destroying SIP dialog '1071657838@xxx.xxx.xxx.xxx6' Method: OPTIONS