Asterisk 1.4.10, Copyright (C) 1999 - 2007 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'core show license' for details. ========================================================================= Connected to Asterisk 1.4.10 currently running on media1 (pid = 655) media1*CLI> -- Remote UNIX connection Verbosity is at least 10 media1*CLI> ag -- Remote UNIX connection media1*CLI> ag -- Remote UNIX connection disconnected media1*CLI> agi debug media1*CLI> AGI Debugging Enabled media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 media1*CLI> <--- SIP read from 69.147.177.196:5061 ---> INVITE sip:1A15085323568@69.147.177.197:5060 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK92ec6ff9a03af2c0b863c839f473ceda;rport Max-Forwards: 70 From: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c To: Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 200 INVITE Contact: Anonymous Expires: 300 User-Agent: Sippy cisco-GUID: 3367343889-1564579435-519358477-718890932 h323-conf-id: 3367343889-1564579435-519358477-718890932 Content-disposition: session Content-Length: 388 Content-Type: application/sdp v=0 o=Sippy 143211660 0 IN IP4 69.147.177.196 s=- t=0 0 m=audio 16444 RTP/AVP 0 2 4 8 18 96 97 98 101 c=IN IP4 75.130.97.187 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: INVITE sip:1A15085323568@69.147.177.197:5060 SIP/2.0 (52) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK92ec6ff9a03af2c0b863c839f473ceda;rport (89) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c (86) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: To: (38) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: b33ea16a-39ffba56@75.130.97.187 (40) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 200 INVITE (16) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Contact: Anonymous (44) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Expires: 300 (12) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: User-Agent: Sippy (17) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: cisco-GUID: 3367343889-1564579435-519358477-718890932 (53) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: h323-conf-id: 3367343889-1564579435-519358477-718890932 (55) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 12: Content-disposition: session (28) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 13: Content-Length: 388 (19) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 14: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 15: (0) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=Sippy 143211660 0 IN IP4 69.147.177.196 (41) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=- (3) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 16444 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 75.130.97.187 (22) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:4 G723/8000 (20) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:18 G729a/8000 (22) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:101 0-15 (15) media1*CLI> --- (15 headers 17 lines) --- media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: b33ea16a-39ffba56@75.130.97.187 (Checking From) --From tag 0f70719a6413dba822df4d062ac60c8c --To-tag media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4488 sip_alloc: Create new SIP channel with our IP: 69.147.177.197 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:2728 do_setnat: Setting NAT on RTP to Off media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4588 sip_alloc: Allocating new SIP dialog for b33ea16a-39ffba56@75.130.97.187 - INVITE (With RTP) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:15226 handle_request: **** Received INVITE (5) - Command in SIP INVITE media1*CLI> Sending to 69.147.177.196 : 5061 (NAT) media1*CLI> Using INVITE request as basis request - b33ea16a-39ffba56@75.130.97.187 media1*CLI> Found peer 'B2BUA_1_1' media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:2728 do_setnat: Setting NAT on RTP to On media1*CLI> Found RTP audio format 0 media1*CLI> Found RTP audio format 2 media1*CLI> Found RTP audio format 4 media1*CLI> Found RTP audio format 8 media1*CLI> Found RTP audio format 18 media1*CLI> Found RTP audio format 96 media1*CLI> Found RTP audio format 97 media1*CLI> Found RTP audio format 98 media1*CLI> Found RTP audio format 101 media1*CLI> Peer audio RTP is at port 75.130.97.187:16444 media1*CLI> Found description format PCMU for ID 0 media1*CLI> Found description format G726-32 for ID 2 media1*CLI> Found description format G723 for ID 4 media1*CLI> Found description format PCMA for ID 8 media1*CLI> Found description format G729a for ID 18 media1*CLI> Found description format G726-40 for ID 96 media1*CLI> Found description format G726-24 for ID 97 media1*CLI> Found description format G726-16 for ID 98 media1*CLI> Found description format telephone-event for ID 101 media1*CLI> Got unsupported a:fmtp in SDP offer media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:5477 process_sdp: T38 state changed to 0 on channel media1*CLI> Capabilities: us - 0x70e (gsm|ulaw|alaw|g729|speex|ilbc), peer - audio=0x90d (g723|ulaw|alaw|g726|g729)/video=0x0 (nothing), combined and ordered- (ulaw|alaw|g729) media1*CLI> Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) media1*CLI> Peer audio RTP is at port 75.130.97.187:16444 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:5568 process_sdp: We're settling with these formats: 0x10c (ulaw|alaw|g729) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:13906 handle_request_invite: Checking SIP call limits for device media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:3195 update_call_counter: Updating call counter for incoming call media1*CLI> Looking for 1A15085323568 in portaum (domain 69.147.177.197) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4054 sip_new: This channel will not be able to handle video. media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:8401 build_route: build_route: Contact hop: Anonymous media1*CLI> list_route: hop: media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:13982 handle_request_invite: SIP/69.147.177.196-0815c000: New call is still down.... Trying... media1*CLI> <--- Transmitting (NAT) to 69.147.177.196:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK92ec6ff9a03af2c0b863c839f473ceda;received=69.147.177.196;rport=5061 From: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c To: Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 200 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 69.147.177.196 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: devicestate.c:287 do_state_change: Changing state for SIP/69.147.177.196 - state 2 (In use) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: pbx.c:1813 pbx_extension_helper: Launching 'SIPDtmfMode' media1*CLI> -- Executing [1A15085323568@portaum:1] SIPDtmfMode("SIP/69.147.177.196-0815c000", "all") in new stack media1*CLI> [Apr 8 15:38:01] DEBUG[655]: pbx.c:1813 pbx_extension_helper: Launching 'AGI' media1*CLI> -- Executing [1A15085323568@portaum:2] AGI("SIP/69.147.177.196-0815c000", "agi://127.0.0.1") in new stack media1*CLI> AGI Tx >> agi_network: yes media1*CLI> [Apr 8 15:38:01] DEBUG[655]: res_agi.c:229 launch_netscript: Wow, connected! media1*CLI> AGI Tx >> agi_request: agi://127.0.0.1 media1*CLI> AGI Tx >> agi_channel: SIP/69.147.177.196-0815c000 media1*CLI> AGI Tx >> agi_language: en AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1239219481.20 AGI Tx >> agi_callerid: 15084252470 AGI Tx >> agi_calleridname: PsYouPhone media1*CLI> AGI Tx >> agi_callingpres: 0 media1*CLI> AGI Tx >> agi_callingani2: 0 media1*CLI> AGI Tx >> agi_callington: 0 AGI Tx >> agi_callingtns: 0 AGI Tx >> agi_dnid: 1A15085323568 AGI Tx >> agi_rdnis: unknown AGI Tx >> agi_context: portaum AGI Tx >> agi_extension: 1A15085323568 AGI Tx >> agi_priority: 2 media1*CLI> AGI Tx >> agi_enhanced: 0.0 AGI Tx >> agi_accountcode: media1*CLI> AGI Tx >> media1*CLI> AGI Rx << GET VARIABLE handoff AGI Tx >> 200 result=0 media1*CLI> AGI Rx << EXEC ANSWER "" -- AGI Script Executing Application: (ANSWER) Options: () media1*CLI> [Apr 8 15:38:01] DEBUG[655]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:3672 sip_answer: SIP answering channel: SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 69.147.177.196 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:6790 transmit_response_with_sdp: Setting framing from config on incoming call media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:6534 add_sdp: ** Our capability: (ulaw|alaw|g729) Video flag: True media1*CLI> Audio is at 69.147.177.197 port 19612 [Apr 8 15:38:01] DEBUG[655]: channel.c:1089 channel_find_locked: Avoiding initial deadlock for channel '0x8161000' media1*CLI> Adding codec 0x4 (ulaw) to SDP media1*CLI> Adding codec 0x100 (g729) to SDP media1*CLI> Adding codec 0x8 (alaw) to SDP media1*CLI> Adding non-codec 0x1 (telephone-event) to SDP media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:6686 add_sdp: -- Done with adding codecs to SDP media1*CLI> [Apr 8 15:38:01] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:6731 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw|g729) media1*CLI> <--- Reliably Transmitting (NAT) to 69.147.177.196:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK92ec6ff9a03af2c0b863c839f473ceda;received=69.147.177.196;rport=5061 From: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c To: ;tag=as48e5e727 Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 200 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 284 v=0 o=root 655 655 IN IP4 69.147.177.197 s=session c=IN IP4 69.147.177.197 t=0 0 m=audio 19612 RTP/AVP 0 18 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:2070 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #68 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> AGI Tx >> 200 result=0 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: devicestate.c:287 do_state_change: Changing state for SIP/69.147.177.196 - state 2 (In use) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 media1*CLI> <--- SIP read from 69.147.177.196:5061 ---> ACK sip:1A15085323568@69.147.177.197 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.196:5061;rport;branch=z9hG4bK4a82ee7c483a0684e9853f7d062a8bce Max-Forwards: 70 From: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c To: ;tag=as48e5e727 Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 200 ACK Expires: 300 User-Agent: Sippy <-------------> media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: ACK sip:1A15085323568@69.147.177.197 SIP/2.0 (44) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.196:5061;rport;branch=z9hG4bK4a82ee7c483a0684e9853f7d062a8bce (89) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Max-Forwards: 70 (16) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c (86) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: To: ;tag=as48e5e727 (53) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: b33ea16a-39ffba56@75.130.97.187 (40) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 200 ACK (13) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Expires: 300 (12) media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: User-Agent: Sippy (17) media1*CLI> --- (9 headers 0 lines) --- media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: b33ea16a-39ffba56@75.130.97.187 (Checking From) --From tag 0f70719a6413dba822df4d062ac60c8c --To-tag as48e5e727 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: b33ea16a-39ffba56@75.130.97.187 Their Tag 0f70719a6413dba822df4d062ac60c8c Our tag: as48e5e727 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:15226 handle_request: **** Received ACK (6) - Command in SIP ACK media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:2181 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #68 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: chan_sip.c:2191 __sip_ack: Stopping retransmission on 'b33ea16a-39ffba56@75.130.97.187' of Response 200: Match Not Found media1*CLI> AGI Rx << GET VARIABLE SIPCALLID media1*CLI> AGI Tx >> 200 result=1 (b33ea16a-39ffba56@75.130.97.187) media1*CLI> AGI Rx << GET VARIABLE SIP_HEADER(h323-conf-id) media1*CLI> AGI Tx >> 200 result=1 (3367343889-1564579435-519358477-718890932) media1*CLI> AGI Rx << SET VARIABLE h323confid 3367343889-1564579435-519358477-718890932 media1*CLI> AGI Tx >> 200 result=1 media1*CLI> AGI Rx << GET VARIABLE SIP_CODEC_USED media1*CLI> AGI Tx >> 200 result=1 (ulaw) media1*CLI> AGI Rx << SET VARIABLE SIP_CODEC ulaw media1*CLI> AGI Tx >> 200 result=1 media1*CLI> AGI Rx << SET VARIABLE _SIP_CODEC ulaw media1*CLI> AGI Tx >> 200 result=1 media1*CLI> AGI Rx << GET VARIABLE CHANNEL media1*CLI> AGI Tx >> 200 result=1 (SIP/69.147.177.196-0815c000) media1*CLI> AGI Rx << GET VARIABLE CHANNEL media1*CLI> AGI Tx >> 200 result=1 (SIP/69.147.177.196-0815c000) media1*CLI> AGI Rx << GET DATA /home/porta-um/apache/prompts//en/lang_sel1 1000 1 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: rtp.c:2718 ast_rtp_write: Ooh, format changed from unknown to ulaw media1*CLI> [Apr 8 15:38:01] DEBUG[655]: rtp.c:2735 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 media1*CLI> [Apr 8 15:38:01] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/lang_sel1' (language 'en') media1*CLI> [Apr 8 15:38:03] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:03] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:04] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '1' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:04] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '1' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:04] DTMF[655]: channel.c:2392 __ast_read: DTMF end '1' received on SIP/69.147.177.196-0815c000, duration 240 ms [Apr 8 15:38:04] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=1, tvdiff=-2026064083 [Apr 8 15:38:04] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:04] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '1' with duration 240 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:04] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '1' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:38:04] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '1' (49) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:04] DTMF[655]: channel.c:3370 ast_readstring_full: Event '1' added to string '1' on SIP/69.147.177.196-0815c000 media1*CLI> AGI Tx >> 200 result=1 media1*CLI> AGI Rx << GET DATA /home/porta-um/apache/prompts//en/enter_card_number 9000 12 media1*CLI> [Apr 8 15:38:04] DEBUG[655]: rtp.c:2592 ast_rtp_raw_write: Difference is 7192, ms is 919 media1*CLI> [Apr 8 15:38:04] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/enter_card_number' (language 'en') media1*CLI> [Apr 8 15:38:07] WARNING[655]: format_pcm.c:101 pcm_read: Short read (0) (No such file or directory)! media1*CLI> [Apr 8 15:38:07] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:07] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:08] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '2' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:08] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '2' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) media1*CLI> [Apr 8 15:38:08] DTMF[655]: channel.c:2392 __ast_read: DTMF end '2' received on SIP/69.147.177.196-0815c000, duration 210 ms media1*CLI> [Apr 8 15:38:08] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=3570 media1*CLI> [Apr 8 15:38:08] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:08] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '2' with duration 210 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:08] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '2' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:08] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '2' (50) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:08] DTMF[655]: channel.c:3370 ast_readstring_full: Event '2' added to string '2' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:08] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '3' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:08] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '3' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:08] DTMF[655]: channel.c:2392 __ast_read: DTMF end '3' received on SIP/69.147.177.196-0815c000, duration 240 ms [Apr 8 15:38:08] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=417 [Apr 8 15:38:08] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:08] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '3' with duration 240 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:09] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '3' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:09] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '3' (51) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:09] DTMF[655]: channel.c:3370 ast_readstring_full: Event '3' added to string '23' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:09] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '9' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:09] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '9' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:09] DTMF[655]: channel.c:2392 __ast_read: DTMF end '9' received on SIP/69.147.177.196-0815c000, duration 240 ms [Apr 8 15:38:09] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=634 [Apr 8 15:38:09] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:09] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '9' with duration 240 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:10] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '9' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:10] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '9' (57) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:10] DTMF[655]: channel.c:3370 ast_readstring_full: Event '9' added to string '239' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:10] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '8' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:10] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '8' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) media1*CLI> [Apr 8 15:38:10] DTMF[655]: channel.c:2392 __ast_read: DTMF end '8' received on SIP/69.147.177.196-0815c000, duration 240 ms media1*CLI> [Apr 8 15:38:10] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=479 media1*CLI> [Apr 8 15:38:10] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:10] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '8' with duration 240 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:10] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '8' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:10] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '8' (56) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:10] DTMF[655]: channel.c:3370 ast_readstring_full: Event '8' added to string '2398' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:11] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '6' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:11] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '6' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:11] DTMF[655]: channel.c:2392 __ast_read: DTMF end '6' received on SIP/69.147.177.196-0815c000, duration 210 ms [Apr 8 15:38:11] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=420 [Apr 8 15:38:11] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:11] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '6' with duration 210 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:11] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '6' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:11] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '6' (54) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:11] DTMF[655]: channel.c:3370 ast_readstring_full: Event '6' added to string '23986' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:11] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) media1*CLI> [Apr 8 15:38:11] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:11] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 210 ms media1*CLI> [Apr 8 15:38:11] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=515 media1*CLI> [Apr 8 15:38:11] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:11] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '4' with duration 210 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:12] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '4' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:12] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '4' (52) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:12] DTMF[655]: channel.c:3370 ast_readstring_full: Event '4' added to string '239864' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:12] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '9' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:12] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '9' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:12] DTMF[655]: channel.c:2392 __ast_read: DTMF end '9' received on SIP/69.147.177.196-0815c000, duration 180 ms [Apr 8 15:38:12] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=510 [Apr 8 15:38:12] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:12] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '9' with duration 180 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:12] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '9' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:12] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '9' (57) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:12] DTMF[655]: channel.c:3370 ast_readstring_full: Event '9' added to string '2398649' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:13] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '7' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:13] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '7' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:13] DTMF[655]: channel.c:2392 __ast_read: DTMF end '7' received on SIP/69.147.177.196-0815c000, duration 210 ms [Apr 8 15:38:13] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=479 [Apr 8 15:38:13] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:13] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '7' with duration 210 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:13] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '7' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:13] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '7' (55) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:13] DTMF[655]: channel.c:3370 ast_readstring_full: Event '7' added to string '23986497' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:14] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:14] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:14] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 240 ms media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=448 [Apr 8 15:38:14] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '4' with duration 240 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '4' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '4' (52) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:3370 ast_readstring_full: Event '4' added to string '239864974' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:14] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '7' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:14] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '7' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:14] DTMF[655]: channel.c:2392 __ast_read: DTMF end '7' received on SIP/69.147.177.196-0815c000, duration 210 ms media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=482 media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:14] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '7' with duration 210 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:15] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '7' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:38:15] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '7' (55) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:15] DTMF[655]: channel.c:3370 ast_readstring_full: Event '7' added to string '2398649747' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:15] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '3' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:15] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '3' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:15] DTMF[655]: channel.c:2392 __ast_read: DTMF end '3' received on SIP/69.147.177.196-0815c000, duration 240 ms [Apr 8 15:38:15] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=480 [Apr 8 15:38:15] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:15] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '3' with duration 240 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:15] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '3' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:15] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '3' (51) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:15] DTMF[655]: channel.c:3370 ast_readstring_full: Event '3' added to string '23986497473' on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:16] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '1' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:16] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '1' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) media1*CLI> [Apr 8 15:38:16] DTMF[655]: channel.c:2392 __ast_read: DTMF end '1' received on SIP/69.147.177.196-0815c000, duration 270 ms [Apr 8 15:38:16] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=359 media1*CLI> [Apr 8 15:38:16] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:16] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '1' with duration 270 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:16] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '1' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:16] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '1' (49) on SIP/69.147.177.196-0815c000 [Apr 8 15:38:16] DTMF[655]: channel.c:3370 ast_readstring_full: Event '1' added to string '239864974731' on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=239864974731 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/you_have *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/you_have' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:38:16] DEBUG[655]: rtp.c:2592 ast_rtp_raw_write: Difference is 69432, ms is 8699 media1*CLI> [Apr 8 15:38:16] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:17] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:17] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals AGI Tx >> 200 result=0 endpos=7296 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/eighty *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/eighty' (escape_digits=*#1234567890f) (sample_offset 0) [Apr 8 15:38:17] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:18] WARNING[655]: format_pcm.c:101 pcm_read: Short read (0) (No such file or directory)! media1*CLI> [Apr 8 15:38:18] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:18] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=7680 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/three *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/three' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:38:18] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:19] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:19] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=6464 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/dollars *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/dollars' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:38:19] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:20] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:38:20] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=8576 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/and *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/and' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:38:20] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:21] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:21] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=8832 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/twenty *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/twenty' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:38:21] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=7936 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/eight *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/eight' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:38:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:38:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=5376 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/cents *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/cents' (escape_digits=*#1234567890f) (sample_offset 0) [Apr 8 15:38:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:24] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:38:24] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=9344 media1*CLI> AGI Rx << GET OPTION /home/porta-um/apache/prompts//en/enter_dest *#1234567890f 9000 media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/enter_dest' (escape_digits=*#1234567890f) (timeout 9000) media1*CLI> [Apr 8 15:38:24] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:26] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:26] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:27] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '1' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:27] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '1' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:27] DTMF[655]: channel.c:2392 __ast_read: DTMF end '1' received on SIP/69.147.177.196-0815c000, duration 270 ms [Apr 8 15:38:27] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=11262 [Apr 8 15:38:27] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:27] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '1' with duration 270 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:27] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '1' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:27] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '1' (49) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=49 endpos=19456 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:28] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '5' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:28] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '5' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:28] DTMF[655]: channel.c:2392 __ast_read: DTMF end '5' received on SIP/69.147.177.196-0815c000, duration 180 ms [Apr 8 15:38:28] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=570 [Apr 8 15:38:28] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:28] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '5' with duration 180 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:28] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '5' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:38:28] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '5' (53) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=53 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:29] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '0' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:29] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '0' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:29] DTMF[655]: channel.c:2392 __ast_read: DTMF end '0' received on SIP/69.147.177.196-0815c000, duration 240 ms [Apr 8 15:38:29] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=324 [Apr 8 15:38:29] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:29] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '0' with duration 240 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:29] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '0' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:29] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '0' (48) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=48 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:29] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '8' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:29] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '8' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:29] DTMF[655]: channel.c:2392 __ast_read: DTMF end '8' received on SIP/69.147.177.196-0815c000, duration 150 ms media1*CLI> [Apr 8 15:38:29] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=140 media1*CLI> [Apr 8 15:38:29] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:29] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '8' with duration 150 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:29] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '8' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:29] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '8' (56) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=56 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:30] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:30] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:30] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 150 ms [Apr 8 15:38:30] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=294 [Apr 8 15:38:30] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:30] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '4' with duration 150 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:30] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '4' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:30] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '4' (52) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=52 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:30] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '2' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:30] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '2' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:30] DTMF[655]: channel.c:2392 __ast_read: DTMF end '2' received on SIP/69.147.177.196-0815c000, duration 210 ms media1*CLI> [Apr 8 15:38:30] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=310 media1*CLI> [Apr 8 15:38:30] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:30] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '2' with duration 210 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:30] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '2' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:30] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '2' (50) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=50 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:30] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '5' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:30] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '5' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:30] DTMF[655]: channel.c:2392 __ast_read: DTMF end '5' received on SIP/69.147.177.196-0815c000, duration 180 ms [Apr 8 15:38:30] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=150 [Apr 8 15:38:30] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:30] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '5' with duration 180 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:31] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '5' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:31] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '5' (53) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=53 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:31] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '2' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:31] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '2' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:31] DTMF[655]: channel.c:2392 __ast_read: DTMF end '2' received on SIP/69.147.177.196-0815c000, duration 180 ms [Apr 8 15:38:31] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=200 [Apr 8 15:38:31] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:31] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '2' with duration 180 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:31] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '2' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:31] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '2' (50) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=50 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:31] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:31] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:31] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 180 ms [Apr 8 15:38:31] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=209 [Apr 8 15:38:31] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:31] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '4' with duration 180 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:31] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '4' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:31] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '4' (52) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=52 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:32] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:32] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:32] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 150 ms [Apr 8 15:38:32] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=181 [Apr 8 15:38:32] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:32] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '4' with duration 150 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:32] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '4' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:32] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '4' (52) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=52 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:32] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '9' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:32] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '9' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:32] DTMF[655]: channel.c:2392 __ast_read: DTMF end '9' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:38:32] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=266 [Apr 8 15:38:32] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:38:32] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '9' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:32] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '9' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:32] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '9' (57) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=57 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:38:32] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '#' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) [Apr 8 15:38:32] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '#' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: b33ea16a-39ffba56@75.130.97.187) media1*CLI> [Apr 8 15:38:32] DTMF[655]: channel.c:2392 __ast_read: DTMF end '#' received on SIP/69.147.177.196-0815c000, duration 180 ms media1*CLI> [Apr 8 15:38:32] DTMF[655]: channel.c:2394 __ast_read: DTMF flags on SIP/69.147.177.196-0815c000 : DEFER_DTMF=0, EMULATE_DTMF=0, IN_DTMF=0, END_DTMF_ONLY=0, tvzero=0, tvdiff=268 media1*CLI> [Apr 8 15:38:32] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:38:32] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '#' with duration 180 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:33] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '#' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE [Apr 8 15:38:33] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '#' (35) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=35 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/you_have *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/you_have' (escape_digits=*#1234567890f) (sample_offset 0) [Apr 8 15:38:33] DEBUG[655]: rtp.c:2592 ast_rtp_raw_write: Difference is 52896, ms is 6632 [Apr 8 15:38:33] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:34] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:34] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=7296 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/one "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/one' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:38:34] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:34] WARNING[655]: format_pcm.c:101 pcm_read: Short read (0) (No such file or directory)! media1*CLI> [Apr 8 15:38:34] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:34] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=7360 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/hundred "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/hundred' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:38:34] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:35] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:38:35] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=8128 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/seventeen "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/seventeen' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:38:35] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:37] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:37] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=9536 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/hours "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/hours' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:38:37] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:38] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:38:38] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=7168 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/and "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/and' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:38:38] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:39] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:39] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=8832 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/six "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/six' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:38:39] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:39] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:38:39] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=7104 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/minutes "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/minutes' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:38:39] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=8256 media1*CLI> AGI Rx << EXEC Set CALLERID(all)=15084252470 <15084252470> media1*CLI> -- AGI Script Executing Application: (Set) Options: (CALLERID(all)=15084252470) media1*CLI> AGI Tx >> 200 result=0 media1*CLI> AGI Rx << EXEC SIPDelHeaders -- AGI Script Executing Application: (SIPDelHeaders) Options: ((null)) media1*CLI> AGI Tx >> 200 result=0 media1*CLI> AGI Rx << EXEC SIPAddHeader h323-conf-id:867561840-987402480-926461410-375977302 media1*CLI> -- AGI Script Executing Application: (SIPAddHeader) Options: (h323-conf-id:867561840-987402480-926461410-375977302) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:17744 sip_addheader: SIP Header added "h323-conf-id:867561840-987402480-926461410-375977302" as _SIPADDHEADER01 to SIP/69.147.177.196-0815c000 media1*CLI> AGI Tx >> 200 result=0 media1*CLI> AGI Rx << EXEC SIPAddHeader H323-incoming-conf-id:867561840-987402480-926461410-375977302 media1*CLI> -- AGI Script Executing Application: (SIPAddHeader) Options: (H323-incoming-conf-id:867561840-987402480-926461410-375977302) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:17744 sip_addheader: SIP Header added "H323-incoming-conf-id:867561840-987402480-926461410-375977302" as _SIPADDHEADER02 to SIP/69.147.177.196-0815c000 media1*CLI> AGI Tx >> 200 result=0 media1*CLI> AGI Rx << SET VARIABLE _SIP_OUTGOING_IP 69.147.177.197 media1*CLI> AGI Tx >> 200 result=1 media1*CLI> AGI Rx << GET VARIABLE SIP_CODEC_USED media1*CLI> AGI Tx >> 200 result=1 (ulaw) media1*CLI> AGI Rx << SET VARIABLE SIP_CODEC ulaw media1*CLI> AGI Tx >> 200 result=1 media1*CLI> AGI Rx << SET VARIABLE _SIP_CODEC ulaw media1*CLI> AGI Tx >> 200 result=1 media1*CLI> AGI Rx << EXEC Dial SIP/15084252449@69.147.177.196||Hm(ringtone)S(9000) -- AGI Script Executing Application: (Dial) Options: (SIP/15084252449@69.147.177.196||Hm(ringtone)S(9000)) -- Setting call duration limit to 9000 seconds. [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4588 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4054 sip_new: This channel will not be able to handle video. media1*CLI> [Apr 8 15:38:41] DEBUG[655]: rtp.c:1606 ast_rtp_make_compatible: Seeded SDP of 'SIP/69.147.177.196-08177000' with that of 'SIP/69.147.177.196-0815c000' media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIP_CODEC. media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIP_OUTGOING_IP. media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER02. media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable h323confid. [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable STACK-portaum-1A15085323568-2. [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable STACK-portaum-1A15085323568-1. [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 8 15:38:41] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIP_CODEC_USED. media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:2953 sip_call: ***************************************************** media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:2954 sip_call: Setting SIP channel SIP/69.147.177.196-08177000 'ourip' to 69.147.177.197 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:3007 sip_call: Outgoing Call for 15084252449 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:3195 update_call_counter: Updating call counter for outgoing call media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:3021 sip_call: Our T38 capability (0), joint T38 capability (0) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:7201 transmit_invite: Adding SIP Header "H323-incoming-conf-id" with content :867561840-987402480-926461410-375977302: [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:7201 transmit_invite: Adding SIP Header "h323-conf-id" with content :867561840-987402480-926461410-375977302: [Apr 8 15:38:41] NOTICE[655]: chan_sip.c:3644 try_suggested_sip_codec: Changing codec to 'ulaw' for this call because of ${SIP_CODEC) variable [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:6534 add_sdp: ** Our capability: (ulaw) Video flag: False Audio is at 69.147.177.197 port 12442 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:6686 add_sdp: -- Done with adding codecs to SDP [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=19) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:6731 add_sdp: Done building SDP. Settling with this capability: (ulaw) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: INVITE sip:15084252449@69.147.177.196 SIP/2.0 (45) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport (65) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: "15084252470" ;tag=as6a654951 (67) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: (36) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Contact: (41) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (56) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: User-Agent: Asterisk PBX (24) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Max-Forwards: 70 (16) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Date: Wed, 08 Apr 2009 19:38:41 GMT (35) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: Supported: replaces (19) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 12: H323-incoming-conf-id: 867561840-987402480-926461410-375977302 (62) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 13: h323-conf-id: 867561840-987402480-926461410-375977302 (53) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 14: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 15: Content-Length: 213 (19) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 16: (0) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=root 655 655 IN IP4 69.147.177.197 (36) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=session (9) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 69.147.177.197 (23) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 12442 RTP/AVP 0 101 (27) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:101 0-16 (15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=ptime:20 (10) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=sendrecv (10) media1*CLI> Reliably Transmitting (no NAT) to 69.147.177.196:5060: INVITE sip:15084252449@69.147.177.196 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport From: "15084252470" ;tag=as6a654951 To: Contact: Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 08 Apr 2009 19:38:41 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces H323-incoming-conf-id: 867561840-987402480-926461410-375977302 h323-conf-id: 867561840-987402480-926461410-375977302 Content-Type: application/sdp Content-Length: 213 v=0 o=root 655 655 IN IP4 69.147.177.197 s=session c=IN IP4 69.147.177.197 t=0 0 m=audio 12442 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:2070 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #70 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> -- Called 15084252449@69.147.177.196 media1*CLI> -- Started music on hold, class 'ringtone', on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: res_musiconhold.c:254 ast_moh_files_next: SIP/69.147.177.196-0815c000 Opened file 0 '/home/porta-um/apache/prompts/ringtone/ringtone' media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 <--- SIP read from 69.147.177.196:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport=5060 To: From: "15084252470" ;tag=as6a654951 Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 CSeq: 102 INVITE Content-Length: 0 <-------------> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 100 Trying (18) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport=5060 (70) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: To: (36) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: "15084252470" ;tag=as6a654951 (67) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (56) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: CSeq: 102 INVITE (16) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Content-Length: 0 (17) --- (7 headers 0 lines) --- [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (Checking To) --From tag as6a654951 --To-tag [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 Their Tag Our tag: as6a654951 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:2224 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #70 - INVITE (got response) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:2233 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '075d517e3036c8fe314f259d3ed79e0c@69.147.177.197' Request 102: Found media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:12089 handle_response_invite: SIP response 100 to standard invite media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 <--- SIP read from 69.147.177.196:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport=5060 Record-Route: To: ;tag=362b35f98affc39cf4a0cce45c20c316 From: "15084252470";tag=as6a654951 Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 CSeq: 102 INVITE Server: Sippy Content-Length: 0 <-------------> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport=5060 (70) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Record-Route: (37) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: ;tag=362b35f98affc39cf4a0cce45c20c316 (73) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: From: "15084252470";tag=as6a654951 (66) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (56) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 102 INVITE (16) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Server: Sippy (13) [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Content-Length: 0 (17) --- (9 headers 0 lines) --- [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (Checking To) --From tag as6a654951 --To-tag 362b35f98affc39cf4a0cce45c20c316 [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 Their Tag Our tag: as6a654951 [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:2233 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '075d517e3036c8fe314f259d3ed79e0c@69.147.177.197' Request 102: Found media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:12089 handle_response_invite: SIP response 180 to standard invite media1*CLI> [Apr 8 15:38:41] DEBUG[655]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/69.147.177.196-08177000 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 69.147.177.196 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:38:41] DEBUG[655]: devicestate.c:287 do_state_change: Changing state for SIP/69.147.177.196 - state 6 (Ringing) media1*CLI> -- SIP/69.147.177.196-08177000 is ringing media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:41] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:42] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: res_musiconhold.c:254 ast_moh_files_next: SIP/69.147.177.196-0815c000 Opened file 0 '/home/porta-um/apache/prompts/ringtone/ringtone' media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:43] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:44] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: res_musiconhold.c:254 ast_moh_files_next: SIP/69.147.177.196-0815c000 Opened file 0 '/home/porta-um/apache/prompts/ringtone/ringtone' media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:45] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:46] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:47] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: res_musiconhold.c:254 ast_moh_files_next: SIP/69.147.177.196-0815c000 Opened file 0 '/home/porta-um/apache/prompts/ringtone/ringtone' media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:48] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:49] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: res_musiconhold.c:254 ast_moh_files_next: SIP/69.147.177.196-0815c000 Opened file 0 '/home/porta-um/apache/prompts/ringtone/ringtone' media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:51] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> -- Remote UNIX connection media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 <--- SIP read from 69.147.177.196:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport=5060 Record-Route: Contact: "Anonymous" To: ;tag=362b35f98affc39cf4a0cce45c20c316 From: "15084252470";tag=as6a654951 Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 CSeq: 102 INVITE Content-Type: application/sdp Server: Sippy Content-Length: 149 v=0 o=Sippy 140704268 1 IN IP4 69.147.177.196 s=SIP Call t=0 0 m=audio 5004 RTP/AVP 0 c=IN IP4 75.130.97.187 a=sendrecv a=rtpmap:0 PCMU/8000 <-------------> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 200 OK (14) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK0a1b2fdc;rport=5060 (70) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Record-Route: (37) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: Contact: "Anonymous" (45) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: To: ;tag=362b35f98affc39cf4a0cce45c20c316 (73) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: From: "15084252470";tag=as6a654951 (66) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (56) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Server: Sippy (13) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: Content-Length: 149 (19) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: (0) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=Sippy 140704268 1 IN IP4 69.147.177.196 (41) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=SIP Call (10) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 5004 RTP/AVP 0 (22) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 75.130.97.187 (22) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=sendrecv (10) media1*CLI> --- (11 headers 8 lines) --- media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (Checking To) --From tag as6a654951 --To-tag 362b35f98affc39cf4a0cce45c20c316 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 Their Tag 362b35f98affc39cf4a0cce45c20c316 Our tag: as6a654951 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:2173 __sip_ack: Acked pending invite 102 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:2191 __sip_ack: Stopping retransmission on '075d517e3036c8fe314f259d3ed79e0c@69.147.177.197' of Request 102: Match Not Found media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:12089 handle_response_invite: SIP response 200 to standard invite media1*CLI> Found RTP audio format 0 media1*CLI> Peer audio RTP is at port 75.130.97.187:5004 media1*CLI> Found description format PCMU for ID 0 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5477 process_sdp: T38 state changed to 0 on channel SIP/69.147.177.196-08177000 media1*CLI> Capabilities: us - 0x70e (gsm|ulaw|alaw|g729|speex|ilbc), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined and ordered- (ulaw) media1*CLI> Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) media1*CLI> Peer audio RTP is at port 75.130.97.187:5004 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5568 process_sdp: We're settling with these formats: 0x4 (ulaw) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5577 process_sdp: We have an owner, now see if we need to change this call media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:3195 update_call_counter: Updating call counter for outgoing call media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:8372 build_route: build_route: Record-Route hop: media1*CLI> list_route: hop: media1*CLI> set_destination: Parsing for address/port to send to media1*CLI> set_destination: set destination to 69.147.177.196, port 5060 media1*CLI> Transmitting (no NAT) to 69.147.177.196:5060: ACK sip:69.147.177.196:5061 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK3cfc2526;rport Route: From: "15084252470" ;tag=as6a654951 To: ;tag=362b35f98affc39cf4a0cce45c20c316 Contact: Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/69.147.177.196-08177000 media1*CLI> -- SIP/69.147.177.196-08177000 answered SIP/69.147.177.196-0815c000 [Apr 8 15:38:52] DEBUG[655]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 69.147.177.196 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: devicestate.c:287 do_state_change: Changing state for SIP/69.147.177.196 - state 2 (In use) media1*CLI> -- Stopped music on hold on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:3091 set_format: Set channel SIP/69.147.177.196-08177000 to write format ulaw media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:3091 set_format: Set channel SIP/69.147.177.196-08177000 to read format ulaw media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:3987 sip_fixup_codecs: Fixup codecs - transmiting reinvite![Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5969 reqprep: Strict routing enforced for session b33ea16a-39ffba56@75.130.97.187 media1*CLI> set_destination: Parsing for address/port to send to media1*CLI> set_destination: set destination to 69.147.177.196, port 5061 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:6534 add_sdp: ** Our capability: (ulaw|alaw|g729) Video flag: True media1*CLI> Audio is at 69.147.177.197 port 19612 media1*CLI> Adding codec 0x4 (ulaw) to SDP media1*CLI> Adding codec 0x100 (g729) to SDP media1*CLI> Adding codec 0x8 (alaw) to SDP media1*CLI> Adding non-codec 0x1 (telephone-event) to SDP media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:6686 add_sdp: -- Done with adding codecs to SDP media1*CLI> [Apr 8 15:38:52] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:6731 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw|g729) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:1662 initialize_initreq: Initializing already initialized SIP dialog b33ea16a-39ffba56@75.130.97.187 (presumably reinvite) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: INVITE sip:69.147.177.196:5061 SIP/2.0 (38) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK794000ff;rport (65) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: ;tag=as48e5e727 (55) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c (84) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Contact: (43) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: b33ea16a-39ffba56@75.130.97.187 (40) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: User-Agent: Asterisk PBX (24) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Max-Forwards: 70 (16) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: Supported: replaces (19) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 12: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 13: Content-Length: 284 (19) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 14: (0) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=root 655 656 IN IP4 69.147.177.197 (36) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=session (9) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 69.147.177.197 (23) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 19612 RTP/AVP 0 18 8 101 (32) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:18 G729/8000 (21) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:18 annexb=no (19) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:101 0-16 (15) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=ptime:20 (10) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=sendrecv (10) media1*CLI> Reliably Transmitting (NAT) to 69.147.177.196:5061: INVITE sip:69.147.177.196:5061 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK794000ff;rport From: ;tag=as48e5e727 To: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c Contact: Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 284 v=0 o=root 655 656 IN IP4 69.147.177.197 s=session c=IN IP4 69.147.177.197 t=0 0 m=audio 19612 RTP/AVP 0 18 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:2070 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #72 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: rtp.c:3263 ast_rtp_bridge: Cannot bridge - one of the channels use InBand DTMF media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 media1*CLI> <--- SIP read from 69.147.177.196:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK794000ff;rport=5060 From: ;tag=as48e5e727 To: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 102 INVITE Server: Sippy <-------------> media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 100 Trying (18) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK794000ff;rport=5060 (70) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: ;tag=as48e5e727 (55) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c (84) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Call-ID: b33ea16a-39ffba56@75.130.97.187 (40) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Server: Sippy (13) media1*CLI> --- (7 headers 0 lines) --- media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: b33ea16a-39ffba56@75.130.97.187 (Checking To) --From tag as48e5e727 --To-tag 0f70719a6413dba822df4d062ac60c8c media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4651 find_call: = No match Their Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 Their Tag 362b35f98affc39cf4a0cce45c20c316 Our tag: as6a654951 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: b33ea16a-39ffba56@75.130.97.187 Their Tag 0f70719a6413dba822df4d062ac60c8c Our tag: as48e5e727 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:2224 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #72 - INVITE (got response) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:2233 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on 'b33ea16a-39ffba56@75.130.97.187' Request 102: Found media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:12087 handle_response_invite: SIP response 100 to RE-invite on outgoing call b33ea16a-39ffba56@75.130.97.187 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 media1*CLI> <--- SIP read from 69.147.177.196:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK794000ff;rport=5060 From: ;tag=as48e5e727 To: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 102 INVITE Server: Sippy Contact: Anonymous Content-Length: 388 Content-Type: application/sdp v=0 o=Sippy 143211660 0 IN IP4 69.147.177.196 s=- t=0 0 m=audio 16444 RTP/AVP 0 2 4 8 18 96 97 98 101 c=IN IP4 75.130.97.187 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 200 OK (14) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK794000ff;rport=5060 (70) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: ;tag=as48e5e727 (55) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c (84) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Call-ID: b33ea16a-39ffba56@75.130.97.187 (40) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Server: Sippy (13) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Contact: Anonymous (44) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Content-Length: 388 (19) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: (0) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=Sippy 143211660 0 IN IP4 69.147.177.196 (41) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=- (3) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 16444 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 75.130.97.187 (22) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:4 G723/8000 (20) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:18 G729a/8000 (22) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:101 0-15 (15) [Apr 8 15:38:52] DEBUG[655]: rtp.c:2718 ast_rtp_write: --- (10 headers 17 lines) --- media1*CLI> Ooh, format changed from unknown to ulaw media1*CLI> [Apr 8 15:38:52] DEBUG[655]: rtp.c:2735 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: b33ea16a-39ffba56@75.130.97.187 (Checking To) --From tag as48e5e727 --To-tag 0f70719a6413dba822df4d062ac60c8c media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4651 find_call: = No match Their Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 Their Tag 362b35f98affc39cf4a0cce45c20c316 Our tag: as6a654951 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: b33ea16a-39ffba56@75.130.97.187 Their Tag 0f70719a6413dba822df4d062ac60c8c Our tag: as48e5e727 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:2173 __sip_ack: Acked pending invite 102 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:2191 __sip_ack: Stopping retransmission on 'b33ea16a-39ffba56@75.130.97.187' of Request 102: Match Not Found media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:12087 handle_response_invite: SIP response 200 to RE-invite on outgoing call b33ea16a-39ffba56@75.130.97.187 media1*CLI> Found RTP audio format 0 media1*CLI> Found RTP audio format 2 media1*CLI> Found RTP audio format 4 media1*CLI> Found RTP audio format 8 media1*CLI> Found RTP audio format 18 media1*CLI> Found RTP audio format 96 media1*CLI> Found RTP audio format 97 media1*CLI> Found RTP audio format 98 media1*CLI> Found RTP audio format 101 media1*CLI> Peer audio RTP is at port 75.130.97.187:16444 media1*CLI> Found description format PCMU for ID 0 media1*CLI> Found description format G726-32 for ID 2 media1*CLI> Found description format G723 for ID 4 media1*CLI> Found description format PCMA for ID 8 media1*CLI> Found description format G729a for ID 18 media1*CLI> Found description format G726-40 for ID 96 media1*CLI> Found description format G726-24 for ID 97 Found description format G726-16 for ID 98 media1*CLI> Found description format telephone-event for ID 101 media1*CLI> Got unsupported a:fmtp in SDP offer media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5477 process_sdp: T38 state changed to 0 on channel SIP/69.147.177.196-0815c000 media1*CLI> Capabilities: us - 0x70e (gsm|ulaw|alaw|g729|speex|ilbc), peer - audio=0x90d (g723|ulaw|alaw|g726|g729)/video=0x0 (nothing), combined and ordered- (ulaw|alaw|g729) media1*CLI> Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) media1*CLI> Peer audio RTP is at port 75.130.97.187:16444 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5568 process_sdp: We're settling with these formats: 0x10c (ulaw|alaw|g729) media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5577 process_sdp: We have an owner, now see if we need to change this call media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:3195 update_call_counter: Updating call counter for incoming call media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:8401 build_route: build_route: Contact hop: Anonymous media1*CLI> list_route: hop: media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:12220 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:12225 handle_response_invite: T38 state changed to 0 on channel SIP media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:12228 handle_response_invite: T38 state changed to 0 on channel SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:5969 reqprep: Strict routing enforced for session b33ea16a-39ffba56@75.130.97.187 media1*CLI> set_destination: Parsing for address/port to send to media1*CLI> set_destination: set destination to 69.147.177.196, port 5061 media1*CLI> Transmitting (NAT) to 69.147.177.196:5061: ACK sip:69.147.177.196:5061 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK45283d7e;rport From: ;tag=as48e5e727 To: PsYouPhone ;tag=0f70719a6413dba822df4d062ac60c8c Contact: Call-ID: b33ea16a-39ffba56@75.130.97.187 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- media1*CLI> [Apr 8 15:38:52] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> -- Remote UNIX connection disconnected media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:15384 sipsock_read: sipsock_read: Received SIP packet on IP 69.147.177.197:5060 <--- SIP read from 69.147.177.196:5060 ---> BYE sip:15084252470@69.147.177.197 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.196:5060;branch=z9hG4bK-d8754z-e704d23fd40a1d12-1---d8754z-;rport Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK675ab8610403783c6612b11e14ad63b9;rport=5061 Max-Forwards: 69 Contact: "Anonymous" To: "15084252470";tag=as6a654951 From: ;tag=362b35f98affc39cf4a0cce45c20c316 Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 CSeq: 100 BYE Expires: 300 User-Agent: Sippy Content-Length: 0 cisco-GUID: 867561840-987402480-926461410-375977302 h323-conf-id: 867561840-987402480-926461410-375977302 <-------------> [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: BYE sip:15084252470@69.147.177.197 SIP/2.0 (42) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.196:5060;branch=z9hG4bK-d8754z-e704d23fd40a1d12-1---d8754z-;rport (93) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK675ab8610403783c6612b11e14ad63b9;rport=5061 (94) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: Max-Forwards: 69 (16) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Contact: "Anonymous" (45) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: To: "15084252470";tag=as6a654951 (64) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: From: ;tag=362b35f98affc39cf4a0cce45c20c316 (75) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (56) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: CSeq: 100 BYE (13) [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Expires: 300 (12) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: User-Agent: Sippy (17) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: Content-Length: 0 (17) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 12: cisco-GUID: 867561840-987402480-926461410-375977302 (51) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4871 parse_request: Header 13: h323-conf-id: 867561840-987402480-926461410-375977302 (53) media1*CLI> ex --- (14 headers 0 lines) --- media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 (Checking From) --From tag 362b35f98affc39cf4a0cce45c20c316 --To-tag as6a654951 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 Their Tag 362b35f98affc39cf4a0cce45c20c316 Our tag: as6a654951 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:15226 handle_request: **** Received BYE (8) - Command in SIP BYE media1*CLI> ex Sending to 69.147.177.196 : 5060 (NAT) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:1674 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/69.147.177.196-08177000 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 69.147.177.196 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:14768 handle_request_bye: Received bye, issuing owner hangup media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 <--- Transmitting (NAT) to 69.147.177.196:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 69.147.177.196:5060;branch=z9hG4bK-d8754z-e704d23fd40a1d12-1---d8754z-;received=69.147.177.196;rport=5060 Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK675ab8610403783c6612b11e14ad63b9;rport=5061 From: ;tag=362b35f98affc39cf4a0cce45c20c316 To: "15084252470";tag=as6a654951 Call-ID: 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197 CSeq: 100 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: channel.c:1089 channel_find_locked: Avoiding initial deadlock for channel '0x817c000' media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: channel.c:4111 ast_generic_bridge: Didn't get a frame from channel: SIP/69.147.177.196-08177000 [Apr 8 15:38:56] DEBUG[655]: channel.c:4436 ast_channel_bridge: Bridge stops bridging channels SIP/69.147.177.196-0815c000 and SIP/69.147.177.196-08177000 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: channel.c:1767 ast_hangup: Hanging up channel 'SIP/69.147.177.196-08177000' media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:3507 sip_hangup: Hangup call SIP/69.147.177.196-08177000, SIP callid 075d517e3036c8fe314f259d3ed79e0c@69.147.177.197) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/69.147.177.196-08177000 [Apr 8 15:38:56] DEBUG[655]: rtp.c:1514 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 8 15:38:56] DEBUG[655]: app_dial.c:1692 dial_exec_full: Exiting with DIALSTATUS=ANSWER. AGI Tx >> 200 result=-1 AGI Rx << GET VARIABLE DIALSTATUS media1*CLI> ex AGI Tx >> 200 result=1 (ANSWER) media1*CLI> ex AGI Rx << GET VARIABLE ANSWEREDTIME media1*CLI> ex AGI Tx >> 200 result=1 (4) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: devicestate.c:287 do_state_change: Changing state for SIP/69.147.177.196 - state 2 (In use) media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 69.147.177.196 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> ex [Apr 8 15:38:56] DEBUG[655]: devicestate.c:287 do_state_change: Changing state for SIP/69.147.177.196 - state 2 (In use) media1*CLI> ex Really destroying SIP dialog '075d517e3036c8fe314f259d3ed79e0c@69.147.177.197' Method: BYE media1*CLI> ex AGI Rx << GET OPTION /home/porta-um/apache/prompts//en/enter_dest_redial *#1234567890f 9000 media1*CLI> ex -- Playing '/home/porta-um/apache/prompts//en/enter_dest_redial' (escape_digits=*#1234567890f) (timeout 9000) [Apr 8 15:38:56] DEBUG[655]: rtp.c:2592 ast_rtp_raw_write: Difference is 9752, ms is 1239 [Apr 8 15:38:56] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> exit