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> Verbosity is at least 10 Core debug is at least 10 media1*CLI> agi debug media1*CLI> AGI Debugging Enabled media1*CLI> [Apr 8 15:26:08] 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:5061 ---> INVITE sip:1A15085323568@69.147.177.197:5060 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bKc0785a081132a9d3bc371f0f3fae1826;rport Max-Forwards: 70 From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 To: Call-ID: 17156d2-c1992d65@75.130.97.187 CSeq: 200 INVITE Contact: Anonymous Expires: 300 User-Agent: Sippy cisco-GUID: 1348029649-598398164-2891166275-3902688990 h323-conf-id: 1348029649-598398164-2891166275-3902688990 Content-disposition: session Content-Length: 388 Content-Type: application/sdp v=0 o=Sippy 141892140 0 IN IP4 69.147.177.196 s=- t=0 0 m=audio 16426 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:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: INVITE sip:1A15085323568@69.147.177.197:5060 SIP/2.0 (52) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bKc0785a081132a9d3bc371f0f3fae1826;rport (89) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 (86) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: To: (38) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 17156d2-c1992d65@75.130.97.187 (39) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 200 INVITE (16) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Contact: Anonymous (44) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Expires: 300 (12) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: User-Agent: Sippy (17) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: cisco-GUID: 1348029649-598398164-2891166275-3902688990 (54) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: h323-conf-id: 1348029649-598398164-2891166275-3902688990 (56) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 12: Content-disposition: session (28) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 13: Content-Length: 388 (19) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 14: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 15: (0) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=Sippy 141892140 0 IN IP4 69.147.177.196 (41) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=- (3) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 16426 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 75.130.97.187 (22) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:4 G723/8000 (20) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:18 G729a/8000 (22) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:26:08] 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:26:08] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 17156d2-c1992d65@75.130.97.187 (Checking From) --From tag fae07a2b3789e338ee721e09f5086ac8 --To-tag media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4488 sip_alloc: Create new SIP channel with our IP: 69.147.177.197 media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:2728 do_setnat: Setting NAT on RTP to Off media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4588 sip_alloc: Allocating new SIP dialog for 17156d2-c1992d65@75.130.97.187 - INVITE (With RTP) media1*CLI> [Apr 8 15:26:08] 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 - 17156d2-c1992d65@75.130.97.187 media1*CLI> Found peer 'B2BUA_1_1' media1*CLI> [Apr 8 15:26:08] 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:16426 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:26:08] 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:16426 media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:5568 process_sdp: We're settling with these formats: 0x10c (ulaw|alaw|g729) media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:13906 handle_request_invite: Checking SIP call limits for device media1*CLI> [Apr 8 15:26:08] 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:26:08] DEBUG[655]: chan_sip.c:4054 sip_new: This channel will not be able to handle video. media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:8401 build_route: build_route: Contact hop: Anonymous media1*CLI> list_route: hop: media1*CLI> [Apr 8 15:26:08] 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=z9hG4bKc0785a081132a9d3bc371f0f3fae1826;received=69.147.177.196;rport=5061 From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 To: Call-ID: 17156d2-c1992d65@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:26:08] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:26:08] 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:26:08] 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:26:08] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:26:08] DEBUG[655]: pbx.c:1813 pbx_extension_helper: Launching 'SIPDtmfMode' media1*CLI> [Apr 8 15:26:08] DEBUG[655]: devicestate.c:287 do_state_change: -- Executing [1A15085323568@portaum:1] SIPDtmfMode("SIP/69.147.177.196-0815c000", "all") in new stack media1*CLI> Changing state for SIP/69.147.177.196 - state 2 (In use) media1*CLI> [Apr 8 15:26:08] 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:26:08] 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 media1*CLI> AGI Tx >> agi_type: SIP AGI Tx >> agi_uniqueid: 1239218768.5 media1*CLI> AGI Tx >> agi_callerid: 15084252470 AGI Tx >> agi_calleridname: PsYouPhone media1*CLI> AGI Tx >> agi_callingpres: 0 AGI Tx >> agi_callingani2: 0 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 media1*CLI> AGI Tx >> agi_priority: 2 AGI Tx >> agi_enhanced: 0.0 media1*CLI> AGI Tx >> agi_accountcode: 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:26:08] 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:26:08] DEBUG[655]: chan_sip.c:3672 sip_answer: SIP answering channel: SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:08] 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:26:08] DEBUG[655]: chan_sip.c:6790 transmit_response_with_sdp: Setting framing from config on incoming call media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:26:08] 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 16954 [Apr 8 15:26:08] 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:26:08] DEBUG[655]: chan_sip.c:6686 add_sdp: -- Done with adding codecs to SDP media1*CLI> [Apr 8 15:26:08] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:26:08] 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=z9hG4bKc0785a081132a9d3bc371f0f3fae1826;received=69.147.177.196;rport=5061 From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 To: ;tag=as5353364c Call-ID: 17156d2-c1992d65@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 16954 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:26:08] DEBUG[655]: chan_sip.c:2070 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #21 media1*CLI> [Apr 8 15:26:08] 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:26:08] 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:26:08] 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:5061 ---> ACK sip:1A15085323568@69.147.177.197 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.196:5061;rport;branch=z9hG4bK62f98b7d1abcb43d9228f647460843ef Max-Forwards: 70 From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 To: ;tag=as5353364c Call-ID: 17156d2-c1992d65@75.130.97.187 CSeq: 200 ACK Expires: 300 User-Agent: Sippy <-------------> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: ACK sip:1A15085323568@69.147.177.197 SIP/2.0 (44) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.196:5061;rport;branch=z9hG4bK62f98b7d1abcb43d9228f647460843ef (89) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 (86) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: To: ;tag=as5353364c (53) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 17156d2-c1992d65@75.130.97.187 (39) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 200 ACK (13) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Expires: 300 (12) [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: User-Agent: Sippy (17) --- (9 headers 0 lines) --- media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 17156d2-c1992d65@75.130.97.187 (Checking From) --From tag fae07a2b3789e338ee721e09f5086ac8 --To-tag as5353364c media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 17156d2-c1992d65@75.130.97.187 Their Tag fae07a2b3789e338ee721e09f5086ac8 Our tag: as5353364c media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:15226 handle_request: **** Received ACK (6) - Command in SIP ACK media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:2181 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #21 media1*CLI> [Apr 8 15:26:08] DEBUG[655]: chan_sip.c:2191 __sip_ack: Stopping retransmission on '17156d2-c1992d65@75.130.97.187' of Response 200: Match Not Found media1*CLI> AGI Rx << GET VARIABLE SIPCALLID media1*CLI> AGI Tx >> 200 result=1 (17156d2-c1992d65@75.130.97.187) media1*CLI> AGI Rx << GET VARIABLE SIP_HEADER(h323-conf-id) media1*CLI> AGI Tx >> 200 result=1 (1348029649-598398164-2891166275-3902688990) media1*CLI> AGI Rx << SET VARIABLE h323confid 1348029649-598398164-2891166275-3902688990 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:26:08] DEBUG[655]: rtp.c:2718 ast_rtp_write: Ooh, format changed from unknown to ulaw media1*CLI> [Apr 8 15:26:08] DEBUG[655]: rtp.c:2735 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 media1*CLI> [Apr 8 15:26:08] 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:26:10] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:10] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:11] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '1' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:11] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '1' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:11] DTMF[655]: channel.c:2392 __ast_read: DTMF end '1' received on SIP/69.147.177.196-0815c000, duration 90 ms [Apr 8 15:26: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=1, tvdiff=-2026777082 [Apr 8 15:26:11] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:11] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '1' with duration 90 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:11] 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:26:11] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '1' (49) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:11] DTMF[655]: channel.c:3370 ast_readstring_full: Event '1' added to string '1' on SIP/69.147.177.196-0815c000 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:26:11] DEBUG[655]: rtp.c:2592 ast_rtp_raw_write: Difference is 5464, ms is 703 [Apr 8 15:26:11] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing '/home/porta-um/apache/prompts//en/enter_card_number' (language 'en') media1*CLI> [Apr 8 15:26:14] WARNING[655]: format_pcm.c:101 pcm_read: Short read (0) (No such file or directory)! media1*CLI> [Apr 8 15:26:14] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:14] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:15] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '2' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:15] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '2' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:15] DTMF[655]: channel.c:2392 __ast_read: DTMF end '2' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26: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=3511 [Apr 8 15:26:15] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:15] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '2' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:15] 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:26:15] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '2' (50) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:15] 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:26:15] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '3' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26: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: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:15] DTMF[655]: channel.c:2392 __ast_read: DTMF end '3' received on SIP/69.147.177.196-0815c000, duration 120 ms media1*CLI> [Apr 8 15:26: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=630 media1*CLI> [Apr 8 15:26:15] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:15] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '3' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26: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:26:15] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '3' (51) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:15] 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:26:16] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '9' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:16] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '9' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:16] DTMF[655]: channel.c:2392 __ast_read: DTMF end '9' received on SIP/69.147.177.196-0815c000, duration 150 ms media1*CLI> [Apr 8 15:26: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=672 media1*CLI> [Apr 8 15:26:16] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:16] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '9' with duration 150 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:16] 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:26:16] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '9' (57) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:16] 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:26:17] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '8' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:17] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '8' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:17] DTMF[655]: channel.c:2392 __ast_read: DTMF end '8' received on SIP/69.147.177.196-0815c000, duration 120 ms media1*CLI> [Apr 8 15:26:17] 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=537 [Apr 8 15:26:17] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:17] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '8' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:17] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '8' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:26:17] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '8' (56) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:17] 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:26:18] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '6' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:18] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '6' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:18] DTMF[655]: channel.c:2392 __ast_read: DTMF end '6' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:18] 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=534 [Apr 8 15:26:18] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:18] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '6' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:18] 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:26:18] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '6' (54) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:18] 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:26:18] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:18] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:18] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:18] 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=630 [Apr 8 15:26:18] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:18] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '4' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:18] 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:26:18] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '4' (52) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:18] 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:26:19] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '9' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:19] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '9' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:19] DTMF[655]: channel.c:2392 __ast_read: DTMF end '9' received on SIP/69.147.177.196-0815c000, duration 120 ms media1*CLI> [Apr 8 15:26:19] 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=642 media1*CLI> [Apr 8 15:26:19] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:19] 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:26:19] 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:26:19] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '9' (57) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:19] 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:26:20] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '7' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:20] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '7' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:20] DTMF[655]: channel.c:2392 __ast_read: DTMF end '7' received on SIP/69.147.177.196-0815c000, duration 120 ms media1*CLI> [Apr 8 15:26:20] 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=599 media1*CLI> [Apr 8 15:26:20] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:20] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '7' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:20] 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:26:20] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '7' (55) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:20] 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:26:21] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:21] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:21] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 150 ms [Apr 8 15:26:21] 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=600 [Apr 8 15:26:21] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:21] 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:26:21] 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:26:21] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '4' (52) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:21] 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:26:21] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '7' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:21] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '7' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:21] DTMF[655]: channel.c:2392 __ast_read: DTMF end '7' received on SIP/69.147.177.196-0815c000, duration 90 ms [Apr 8 15:26:21] 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=443 [Apr 8 15:26:21] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:21] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '7' with duration 90 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:21] 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:26:21] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '7' (55) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:21] 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:26:22] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '3' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:22] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '3' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:22] DTMF[655]: channel.c:2392 __ast_read: DTMF end '3' received on SIP/69.147.177.196-0815c000, duration 90 ms media1*CLI> [Apr 8 15:26:22] 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=562 media1*CLI> [Apr 8 15:26:22] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:22] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '3' with duration 90 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:22] 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:26:22] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '3' (51) on SIP/69.147.177.196-0815c000 [Apr 8 15:26:22] 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:26:23] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '1' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:23] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '1' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:23] DTMF[655]: channel.c:2392 __ast_read: DTMF end '1' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:23] 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=637 [Apr 8 15:26:23] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:23] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '1' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:23] 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:26:23] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '1' (49) on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:23] DTMF[655]: channel.c:3370 ast_readstring_full: Event '1' added to string '239864974731' on SIP/69.147.177.196-0815c000 media1*CLI> 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:26:23] DEBUG[655]: rtp.c:2592 ast_rtp_raw_write: Difference is 69248, ms is 8676 media1*CLI> [Apr 8 15:26:23] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:24] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:24] 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:26:24] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:25] WARNING[655]: format_pcm.c:101 pcm_read: Short read (0) (No such file or directory)! [Apr 8 15:26:25] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:26:25] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals 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:26:25] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:25] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:25] 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:26:25] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:27] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:27] 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:26:27] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:28] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:28] 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/sixty *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/sixty' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:26:28] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:29] WARNING[655]: format_pcm.c:101 pcm_read: Short read (0) (No such file or directory)! [Apr 8 15:26:29] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:29] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=8000 media1*CLI> AGI Rx << STREAM FILE /home/porta-um/apache/prompts//en/numbers/two *#1234567890f media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/two' (escape_digits=*#1234567890f) (sample_offset 0) media1*CLI> [Apr 8 15:26:29] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:29] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:29] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=5312 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) media1*CLI> [Apr 8 15:26:29] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:30] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:30] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals 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:26:30] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:33] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:26:33] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:34] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '1' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:34] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '1' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:34] DTMF[655]: channel.c:2392 __ast_read: DTMF end '1' received on SIP/69.147.177.196-0815c000, duration 180 ms [Apr 8 15:26:34] 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=11088 [Apr 8 15:26:34] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:34] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '1' with duration 180 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:34] 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:26:34] 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 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:34] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '5' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:34] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '5' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:34] DTMF[655]: channel.c:2392 __ast_read: DTMF end '5' received on SIP/69.147.177.196-0815c000, duration 120 ms media1*CLI> [Apr 8 15:26:34] 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=356 media1*CLI> [Apr 8 15:26:34] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:34] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '5' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:35] 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:26:35] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '5' (53) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=53 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:35] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '0' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:35] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '0' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:35] DTMF[655]: channel.c:2392 __ast_read: DTMF end '0' received on SIP/69.147.177.196-0815c000, duration 150 ms [Apr 8 15:26:35] 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:26:35] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:35] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '0' with duration 150 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:35] 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:26:35] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '0' (48) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=48 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:36] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '8' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:36] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '8' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:36] DTMF[655]: channel.c:2392 __ast_read: DTMF end '8' received on SIP/69.147.177.196-0815c000, duration 210 ms media1*CLI> [Apr 8 15:26:36] 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=390 media1*CLI> [Apr 8 15:26:36] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:36] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '8' with duration 210 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:36] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '8' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:26:36] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '8' (56) on SIP/69.147.177.196-0815c000 media1*CLI> AGI Tx >> 200 result=56 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:37] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '8' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:37] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '8' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:37] DTMF[655]: channel.c:2392 __ast_read: DTMF end '8' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:37] 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=1679 [Apr 8 15:26:37] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:37] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '8' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:38] 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:26:38] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '8' (56) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=56 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:38] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '6' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:38] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '6' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:38] DTMF[655]: channel.c:2392 __ast_read: DTMF end '6' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:38] 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=370 media1*CLI> [Apr 8 15:26:38] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:38] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '6' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:38] 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:26:38] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '6' (54) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=54 AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:38] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '9' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:38] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '9' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:26:38] DTMF[655]: channel.c:2392 __ast_read: DTMF end '9' received on SIP/69.147.177.196-0815c000, duration 180 ms media1*CLI> [Apr 8 15:26:38] 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=387 media1*CLI> [Apr 8 15:26:38] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:38] 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:26:39] 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:26:39] 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:26:39] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '3' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:39] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '3' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:39] DTMF[655]: channel.c:2392 __ast_read: DTMF end '3' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:39] 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=389 [Apr 8 15:26:39] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:39] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '3' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:39] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '3' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:26:39] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '3' (51) on SIP/69.147.177.196-0815c000 media1*CLI> AGI Tx >> 200 result=51 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:40] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '4' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:40] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '4' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:40] DTMF[655]: channel.c:2392 __ast_read: DTMF end '4' received on SIP/69.147.177.196-0815c000, duration 150 ms [Apr 8 15:26:40] 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=396 [Apr 8 15:26:40] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:40] 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:26:40] 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:26:40] 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:26:40] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '6' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:40] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '6' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:40] DTMF[655]: channel.c:2392 __ast_read: DTMF end '6' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:40] 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=322 [Apr 8 15:26:40] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:40] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '6' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:40] 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:26:40] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '6' (54) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=54 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:40] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '6' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:40] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '6' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:40] DTMF[655]: channel.c:2392 __ast_read: DTMF end '6' received on SIP/69.147.177.196-0815c000, duration 90 ms media1*CLI> [Apr 8 15:26:40] 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=272 media1*CLI> [Apr 8 15:26:40] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' media1*CLI> [Apr 8 15:26:40] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '6' with duration 90 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:41] 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:26:41] DTMF[655]: channel.c:2126 ast_waitfordigit_full: Got event: '6' (54) on SIP/69.147.177.196-0815c000 AGI Tx >> 200 result=54 media1*CLI> AGI Rx << WAIT FOR DIGIT 9000 media1*CLI> [Apr 8 15:26:41] DEBUG[655]: chan_sip.c:4352 sip_rtp_read: * Detected inband DTMF '#' on channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:41] DEBUG[655]: chan_sip.c:4362 sip_rtp_read: * Pass inband DTMF '#' to core, channel 'SIP/69.147.177.196-0815c000' (Call-ID: 17156d2-c1992d65@75.130.97.187) [Apr 8 15:26:41] DTMF[655]: channel.c:2392 __ast_read: DTMF end '#' received on SIP/69.147.177.196-0815c000, duration 120 ms [Apr 8 15:26:41] 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=382 [Apr 8 15:26:41] DTMF[655]: channel.c:2401 __ast_read: DTMF queue on SIP/69.147.177.196-0815c000 :'' [Apr 8 15:26:41] DTMF[655]: channel.c:2439 __ast_read: DTMF begin emulation of '#' with duration 120 queued on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:41] DTMF[655]: channel.c:2536 __ast_read: DTMF end emulation of '#' queued on SIP/69.147.177.196-0815c000 by AST_FRAME_VOICE media1*CLI> [Apr 8 15:26:41] 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:26:41] DEBUG[655]: rtp.c:2592 ast_rtp_raw_write: Difference is 66104, ms is 8283 [Apr 8 15:26:41] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:42] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:42] 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:26:42] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:43] WARNING[655]: format_pcm.c:101 pcm_read: Short read (0) (No such file or directory)! media1*CLI> [Apr 8 15:26:43] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:43] 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:26:43] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:44] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:26:44] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals 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:26:44] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:45] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:45] 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:26:45] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:46] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:26:46] 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:26:46] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:47] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:47] 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/thirty "" media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/numbers/thirty' (escape_digits=) (sample_offset 0) media1*CLI> [Apr 8 15:26:47] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:48] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:48] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> AGI Tx >> 200 result=0 endpos=6912 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:26:48] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:49] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:49] 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:26:49] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:50] 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 media1*CLI> -- AGI Script Executing Application: (SIPDelHeaders) Options: ((null)) media1*CLI> AGI Tx >> 200 result=0 media1*CLI> AGI Rx << EXEC SIPAddHeader h323-conf-id:2519709970-4077338400-2857134154-2660613908 media1*CLI> -- AGI Script Executing Application: (SIPAddHeader) Options: (h323-conf-id:2519709970-4077338400-2857134154-2660613908) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:17744 sip_addheader: SIP Header added "h323-conf-id:2519709970-4077338400-2857134154-2660613908" 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:2519709970-4077338400-2857134154-2660613908 media1*CLI> -- AGI Script Executing Application: (SIPAddHeader) Options: (H323-incoming-conf-id:2519709970-4077338400-2857134154-2660613908) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:17744 sip_addheader: SIP Header added "H323-incoming-conf-id:2519709970-4077338400-2857134154-2660613908" 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/15088693466@69.147.177.196||Hm(ringtone)S(3601) media1*CLI> -- AGI Script Executing Application: (Dial) Options: (SIP/15088693466@69.147.177.196||Hm(ringtone)S(3601)) media1*CLI> -- Setting call duration limit to 3601 seconds. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4588 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4054 sip_new: This channel will not be able to handle video. media1*CLI> [Apr 8 15:26:50] 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:26:50] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIP_CODEC. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIP_OUTGOING_IP. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER02. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3598 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable h323confid. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable STACK-portaum-1A15085323568-2. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable STACK-portaum-1A15085323568-1. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPCALLID. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIPURI. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:3611 ast_channel_inherit_variables: Not copying variable SIP_CODEC_USED. media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:2953 sip_call: ***************************************************** media1*CLI> [Apr 8 15:26:50] 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:26:50] DEBUG[655]: chan_sip.c:3007 sip_call: Outgoing Call for 15088693466 media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:3195 update_call_counter: Updating call counter for outgoing call media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:3021 sip_call: Our T38 capability (0), joint T38 capability (0) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:7201 transmit_invite: Adding SIP Header "H323-incoming-conf-id" with content :2519709970-4077338400-2857134154-2660613908: media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:7201 transmit_invite: Adding SIP Header "h323-conf-id" with content :2519709970-4077338400-2857134154-2660613908: media1*CLI> [Apr 8 15:26:50] NOTICE[655]: chan_sip.c:3644 try_suggested_sip_codec: Changing codec to 'ulaw' for this call because of ${SIP_CODEC) variable media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:6534 add_sdp: ** Our capability: (ulaw) Video flag: False media1*CLI> Audio is at 69.147.177.197 port 16160 media1*CLI> Adding codec 0x4 (ulaw) to SDP media1*CLI> Adding non-codec 0x1 (telephone-event) to SDP media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:6686 add_sdp: -- Done with adding codecs to SDP media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=19) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:6731 add_sdp: Done building SDP. Settling with this capability: (ulaw) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: INVITE sip:15088693466@69.147.177.196 SIP/2.0 (45) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK6acdd21d;rport (65) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: "15084252470" ;tag=as03556fe4 (67) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: (36) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Contact: (41) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (56) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: User-Agent: Asterisk PBX (24) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Max-Forwards: 70 (16) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Date: Wed, 08 Apr 2009 19:26:50 GMT (35) media1*CLI> [Apr 8 15:26:50] 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:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: Supported: replaces (19) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 12: H323-incoming-conf-id: 2519709970-4077338400-2857134154-2660613908 (66) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 13: h323-conf-id: 2519709970-4077338400-2857134154-2660613908 (57) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 14: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 15: Content-Length: 213 (19) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 16: (0) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:26:50] 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:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=session (9) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 69.147.177.197 (23) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 16160 RTP/AVP 0 101 (27) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:101 0-16 (15) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=ptime:20 (10) media1*CLI> [Apr 8 15:26:50] 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:15088693466@69.147.177.196 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK6acdd21d;rport From: "15084252470" ;tag=as03556fe4 To: Contact: Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 08 Apr 2009 19:26:50 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces H323-incoming-conf-id: 2519709970-4077338400-2857134154-2660613908 h323-conf-id: 2519709970-4077338400-2857134154-2660613908 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 16160 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:26:50] DEBUG[655]: chan_sip.c:2070 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #23 media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> -- Called 15088693466@69.147.177.196 media1*CLI> -- Started music on hold, class 'ringtone', on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:50] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 160 sample intervals media1*CLI> [Apr 8 15:26: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:26: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:26:50] 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=z9hG4bK6acdd21d;rport=5060 To: From: "15084252470" ;tag=as03556fe4 Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 CSeq: 102 INVITE Content-Length: 0 <-------------> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 100 Trying (18) [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK6acdd21d;rport=5060 (70) [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: To: (36) [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: "15084252470" ;tag=as03556fe4 (67) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (56) [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Content-Length: 0 (17) media1*CLI> --- (7 headers 0 lines) --- media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (Checking To) --From tag as03556fe4 --To-tag [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 Their Tag Our tag: as03556fe4 media1*CLI> [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:2224 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #23 - INVITE (got response) [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:2233 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '450ebed15fd1505313aceed3254a6618@69.147.177.197' Request 102: Found [Apr 8 15:26:50] DEBUG[655]: chan_sip.c:12089 handle_response_invite: SIP response 100 to standard invite media1*CLI> [Apr 8 15:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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:26: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 183 Session Progress Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK6acdd21d;rport=5060 Record-Route: To: ;tag=72336e580e055d18f3c0f46c171ddfaa From: "15084252470";tag=as03556fe4 Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 CSeq: 102 INVITE Content-Type: application/sdp Server: Sippy Content-Length: 186 v=0 o=Sippy 141746348 1 IN IP4 69.147.177.196 s=- t=0 0 m=audio 22944 RTP/AVP 0 101 c=IN IP4 208.69.56.54 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK6acdd21d;rport=5060 (70) [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Record-Route: (37) [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: ;tag=72336e580e055d18f3c0f46c171ddfaa (73) [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: From: "15084252470";tag=as03556fe4 (66) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (56) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Server: Sippy (13) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Content-Length: 186 (19) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: (0) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=Sippy 141746348 1 IN IP4 69.147.177.196 (41) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=- (3) [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 22944 RTP/AVP 0 101 (27) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 208.69.56.54 (21) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> --- (10 headers 9 lines) --- media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (Checking To) --From tag as03556fe4 --To-tag 72336e580e055d18f3c0f46c171ddfaa media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 Their Tag Our tag: as03556fe4 media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:2233 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '450ebed15fd1505313aceed3254a6618@69.147.177.197' Request 102: Found media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:12089 handle_response_invite: SIP response 183 to standard invite media1*CLI> Found RTP audio format 0 media1*CLI> Found RTP audio format 101 media1*CLI> Peer audio RTP is at port 208.69.56.54:22944 media1*CLI> Found description format PCMU for ID 0 media1*CLI> Found description format telephone-event for ID 101 media1*CLI> Got unsupported a:fmtp in SDP offer media1*CLI> [Apr 8 15:26: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 - 0x1 (telephone-event), combined - 0x1 (telephone-event) media1*CLI> Peer audio RTP is at port 208.69.56.54:22944 media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:5568 process_sdp: We're settling with these formats: 0x4 (ulaw) media1*CLI> [Apr 8 15:26:52] DEBUG[655]: chan_sip.c:5577 process_sdp: We have an owner, now see if we need to change this call media1*CLI> -- SIP/69.147.177.196-08177000 is making progress passing it to SIP/69.147.177.196-0815c000 media1*CLI> -- Stopped music on hold on SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:26:52] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals media1*CLI> [Apr 8 15:26:52] DEBUG[655]: rtp.c:2718 ast_rtp_write: Ooh, format changed from unknown to ulaw media1*CLI> [Apr 8 15:26:52] DEBUG[655]: rtp.c:2735 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 media1*CLI> -- Remote UNIX connection disconnected media1*CLI> [Apr 8 15:26:55] DEBUG[655]: rtp.c:885 ast_rtcp_read: Got RTCP report of 52 bytes media1*CLI> [Apr 8 15:26:57] DEBUG[655]: rtp.c:885 ast_rtcp_read: Got RTCP report of 52 bytes media1*CLI> [Apr 8 15:27:02] DEBUG[655]: rtp.c:885 ast_rtcp_read: Got RTCP report of 52 bytes media1*CLI> [Apr 8 15:27:06] DEBUG[655]: rtp.c:885 ast_rtcp_read: Got RTCP report of 52 bytes media1*CLI> [Apr 8 15:27:10] DEBUG[655]: rtp.c:885 ast_rtcp_read: Got RTCP report of 52 bytes media1*CLI> [Apr 8 15:27:12] 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=z9hG4bK6acdd21d;rport=5060 Record-Route: Contact: "Anonymous" To: ;tag=72336e580e055d18f3c0f46c171ddfaa From: "15084252470";tag=as03556fe4 Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 CSeq: 102 INVITE Content-Type: application/sdp Server: Sippy Content-Length: 186 v=0 o=Sippy 141746348 2 IN IP4 69.147.177.196 s=- t=0 0 m=audio 22944 RTP/AVP 0 101 c=IN IP4 208.69.56.54 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK6acdd21d;rport=5060 (70) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Record-Route: (37) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: Contact: "Anonymous" (45) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: To: ;tag=72336e580e055d18f3c0f46c171ddfaa (73) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: From: "15084252470";tag=as03556fe4 (66) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (56) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Server: Sippy (13) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: Content-Length: 186 (19) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: (0) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=Sippy 141746348 2 IN IP4 69.147.177.196 (41) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=- (3) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 22944 RTP/AVP 0 101 (27) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 208.69.56.54 (21) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> --- (11 headers 9 lines) --- media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (Checking To) --From tag as03556fe4 --To-tag 72336e580e055d18f3c0f46c171ddfaa media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 Their Tag 72336e580e055d18f3c0f46c171ddfaa Our tag: as03556fe4 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:2173 __sip_ack: Acked pending invite 102 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:2191 __sip_ack: Stopping retransmission on '450ebed15fd1505313aceed3254a6618@69.147.177.197' of Request 102: Match Not Found media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:12089 handle_response_invite: SIP response 200 to standard invite media1*CLI> Found RTP audio format 0 media1*CLI> Found RTP audio format 101 media1*CLI> Peer audio RTP is at port 208.69.56.54:22944 media1*CLI> Found description format PCMU for ID 0 media1*CLI> Found description format telephone-event for ID 101 media1*CLI> Got unsupported a:fmtp in SDP offer media1*CLI> [Apr 8 15:27:12] 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 - 0x1 (telephone-event), combined - 0x1 (telephone-event) media1*CLI> Peer audio RTP is at port 208.69.56.54:22944 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:5568 process_sdp: We're settling with these formats: 0x4 (ulaw) media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:3195 update_call_counter: Updating call counter for outgoing call media1*CLI> [Apr 8 15:27:12] 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=z9hG4bK6dc460df;rport Route: From: "15084252470" ;tag=as03556fe4 To: ;tag=72336e580e055d18f3c0f46c171ddfaa Contact: Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:27:12] 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 -- SIP/69.147.177.196-08177000 answered SIP/69.147.177.196-0815c000 media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: channel.c:3091 set_format: Set channel SIP/69.147.177.196-08177000 to write format ulaw media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: channel.c:3091 set_format: Set channel SIP/69.147.177.196-08177000 to read format ulaw media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:3987 sip_fixup_codecs: Fixup codecs - transmiting reinvite![Apr 8 15:27:12] DEBUG[655]: chan_sip.c:5969 reqprep: Strict routing enforced for session 17156d2-c1992d65@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:27:12] 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 16954 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:27:12] DEBUG[655]: chan_sip.c:6686 add_sdp: -- Done with adding codecs to SDP media1*CLI> [Apr 8 15:27:12] DEBUG[655]: channel.c:2615 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=15) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:6731 add_sdp: Done building SDP. Settling with this capability: (ulaw|alaw|g729) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:1662 initialize_initreq: Initializing already initialized SIP dialog 17156d2-c1992d65@75.130.97.187 (presumably reinvite) media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK597641b5;rport (65) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: ;tag=as5353364c (55) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 (84) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Contact: (43) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 17156d2-c1992d65@75.130.97.187 (39) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: User-Agent: Asterisk PBX (24) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Max-Forwards: 70 (16) media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: Supported: replaces (19) media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 12: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 13: Content-Length: 284 (19) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 14: (0) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=session (9) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 69.147.177.197 (23) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 16954 RTP/AVP 0 18 8 101 (32) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:18 G729/8000 (21) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:18 annexb=no (19) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:101 0-16 (15) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=ptime:20 (10) media1*CLI> [Apr 8 15:27:12] 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=z9hG4bK597641b5;rport From: ;tag=as5353364c To: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 Contact: Call-ID: 17156d2-c1992d65@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 16954 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:27:12] DEBUG[655]: chan_sip.c:2070 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #26 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: rtp.c:3263 ast_rtp_bridge: Cannot bridge - one of the channels use InBand DTMF media1*CLI> [Apr 8 15:27:12] 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:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK597641b5;rport=5060 From: ;tag=as5353364c To: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 Call-ID: 17156d2-c1992d65@75.130.97.187 CSeq: 102 INVITE Server: Sippy <-------------> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 100 Trying (18) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK597641b5;rport=5060 (70) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: ;tag=as5353364c (55) [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 (84) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Call-ID: 17156d2-c1992d65@75.130.97.187 (39) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Server: Sippy (13) media1*CLI> --- (7 headers 0 lines) --- media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 17156d2-c1992d65@75.130.97.187 (Checking To) --From tag as5353364c --To-tag fae07a2b3789e338ee721e09f5086ac8 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4651 find_call: = No match Their Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 Their Tag 72336e580e055d18f3c0f46c171ddfaa Our tag: as03556fe4 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 17156d2-c1992d65@75.130.97.187 Their Tag fae07a2b3789e338ee721e09f5086ac8 Our tag: as5353364c media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:2224 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #26 - INVITE (got response) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:2233 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '17156d2-c1992d65@75.130.97.187' Request 102: Found media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:12087 handle_response_invite: SIP response 100 to RE-invite on outgoing call 17156d2-c1992d65@75.130.97.187 media1*CLI> [Apr 8 15:27:12] 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=z9hG4bK597641b5;rport=5060 From: ;tag=as5353364c To: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 Call-ID: 17156d2-c1992d65@75.130.97.187 CSeq: 102 INVITE Server: Sippy Contact: Anonymous Content-Length: 388 Content-Type: application/sdp v=0 o=Sippy 141892140 0 IN IP4 69.147.177.196 s=- t=0 0 m=audio 16426 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:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 200 OK (14) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK597641b5;rport=5060 (70) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: From: ;tag=as5353364c (55) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: To: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 (84) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Call-ID: 17156d2-c1992d65@75.130.97.187 (39) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: CSeq: 102 INVITE (16) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Server: Sippy (13) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Contact: Anonymous (44) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Content-Length: 388 (19) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: Content-Type: application/sdp (29) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: (0) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: v=0 (3) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: o=Sippy 141892140 0 IN IP4 69.147.177.196 (41) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: s=- (3) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: t=0 0 (5) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: m=audio 16426 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: c=IN IP4 75.130.97.187 (22) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:4 G723/8000 (20) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:18 G729a/8000 (22) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4903 parse_request: Line: a=fmtp:101 0-15 (15) media1*CLI> --- (10 headers 17 lines) --- media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 17156d2-c1992d65@75.130.97.187 (Checking To) --From tag as5353364c --To-tag fae07a2b3789e338ee721e09f5086ac8 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4651 find_call: = No match Their Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 Their Tag 72336e580e055d18f3c0f46c171ddfaa Our tag: as03556fe4 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 17156d2-c1992d65@75.130.97.187 Their Tag fae07a2b3789e338ee721e09f5086ac8 Our tag: as5353364c media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:2173 __sip_ack: Acked pending invite 102 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:2191 __sip_ack: Stopping retransmission on '17156d2-c1992d65@75.130.97.187' of Request 102: Match Not Found media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:12087 handle_response_invite: SIP response 200 to RE-invite on outgoing call 17156d2-c1992d65@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:16426 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:27:12] 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:16426 media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:5568 process_sdp: We're settling with these formats: 0x10c (ulaw|alaw|g729) media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:3195 update_call_counter: Updating call counter for incoming call media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:8401 build_route: build_route: Contact hop: Anonymous media1*CLI> list_route: hop: media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:12225 handle_response_invite: T38 state changed to 0 on channel SIP media1*CLI> [Apr 8 15:27:12] 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:27:12] DEBUG[655]: chan_sip.c:5969 reqprep: Strict routing enforced for session 17156d2-c1992d65@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=z9hG4bK2667dcad;rport From: ;tag=as5353364c To: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 Contact: Call-ID: 17156d2-c1992d65@75.130.97.187 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- media1*CLI> [Apr 8 15:27:12] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:27:17] DEBUG[655]: rtp.c:885 ast_rtcp_read: Got RTCP report of 52 bytes media1*CLI> [Apr 8 15:27:22] 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:5061 ---> BYE sip:1A15085323568@69.147.177.197 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK90388af726015cacfb474d76cb60b620;rport Max-Forwards: 70 From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 To: ;tag=as5353364c Call-ID: 17156d2-c1992d65@75.130.97.187 CSeq: 201 BYE Contact: Anonymous Expires: 300 User-Agent: Sippy cisco-GUID: 1348029649-598398164-2891166275-3902688990 h323-conf-id: 1348029649-598398164-2891166275-3902688990 <-------------> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: BYE sip:1A15085323568@69.147.177.197 SIP/2.0 (44) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK90388af726015cacfb474d76cb60b620;rport (89) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: Max-Forwards: 70 (16) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 (86) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: To: ;tag=as5353364c (53) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: Call-ID: 17156d2-c1992d65@75.130.97.187 (39) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: CSeq: 201 BYE (13) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Contact: Anonymous (44) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 8: Expires: 300 (12) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 9: User-Agent: Sippy (17) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 10: cisco-GUID: 1348029649-598398164-2891166275-3902688990 (54) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 11: h323-conf-id: 1348029649-598398164-2891166275-3902688990 (56) --- (12 headers 0 lines) --- media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 17156d2-c1992d65@75.130.97.187 (Checking From) --From tag fae07a2b3789e338ee721e09f5086ac8 --To-tag as5353364c [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4651 find_call: = No match Their Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 Their Tag 72336e580e055d18f3c0f46c171ddfaa Our tag: as03556fe4 media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 17156d2-c1992d65@75.130.97.187 Their Tag fae07a2b3789e338ee721e09f5086ac8 Our tag: as5353364c media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:15226 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 69.147.177.196 : 5061 (NAT) media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:1674 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 17156d2-c1992d65@75.130.97.187 media1*CLI> [Apr 8 15:27:22] 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:27:22] DEBUG[655]: chan_sip.c:14768 handle_request_bye: Received bye, issuing owner hangup media1*CLI> [Apr 8 15:27:22] DEBUG[655]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 69.147.177.196 media1*CLI> <--- Transmitting (NAT) to 69.147.177.196:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 69.147.177.196:5061;branch=z9hG4bK90388af726015cacfb474d76cb60b620;received=69.147.177.196;rport=5061 From: PsYouPhone ;tag=fae07a2b3789e338ee721e09f5086ac8 To: ;tag=as5353364c Call-ID: 17156d2-c1992d65@75.130.97.187 CSeq: 201 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:27:22] 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:27:22] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 media1*CLI> [Apr 8 15:27:22] DEBUG[655]: channel.c:4111 ast_generic_bridge: Didn't get a frame from channel: SIP/69.147.177.196-0815c000 [Apr 8 15:27:22] 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> [Apr 8 15:27:22] DEBUG[655]: channel.c:1767 ast_hangup: Hanging up channel 'SIP/69.147.177.196-08177000' [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:3507 sip_hangup: Hangup call SIP/69.147.177.196-08177000, SIP callid 450ebed15fd1505313aceed3254a6618@69.147.177.197) Scheduling destruction of SIP dialog '450ebed15fd1505313aceed3254a6618@69.147.177.197' in 32000 ms (Method: INVITE) media1*CLI> set_destination: Parsing for address/port to send to set_destination: set destination to 69.147.177.196, port 5060 media1*CLI> Reliably Transmitting (no NAT) to 69.147.177.196:5060: BYE sip:69.147.177.196:5061 SIP/2.0 Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK297cad7d;rport Route: From: "15084252470" ;tag=as03556fe4 To: ;tag=72336e580e055d18f3c0f46c171ddfaa Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:2070 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #28 [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:1797 __sip_xmit: Will send SIP packet from 69.147.177.197:5060 [Apr 8 15:27:22] 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:27:22] DEBUG[655]: rtp.c:1514 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 8 15:27:22] DEBUG[655]: app_dial.c:1692 dial_exec_full: Exiting with DIALSTATUS=ANSWER. AGI Tx >> 200 result=-1 [Apr 8 15:27:22] 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:27:22] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 [Apr 8 15:27:22] 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:27:22] DEBUG[655]: res_agi.c:1865 run_agi: SIP/69.147.177.196-0815c000 hungup media1*CLI> AGI Rx << GET VARIABLE DIALSTATUS AGI Tx >> 200 result=1 (ANSWER) media1*CLI> AGI Rx << GET VARIABLE ANSWEREDTIME media1*CLI> AGI Tx >> 200 result=1 (10) media1*CLI> [Apr 8 15:27:22] 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=z9hG4bK297cad7d;rport=5060 To: ;tag=72336e580e055d18f3c0f46c171ddfaa From: "15084252470";tag=as03556fe4 Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 CSeq: 103 BYE Server: Sippy Content-Length: 0 <-------------> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 1: Via: SIP/2.0/UDP 69.147.177.197:5060;branch=z9hG4bK297cad7d;rport=5060 (70) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 2: To: ;tag=72336e580e055d18f3c0f46c171ddfaa (73) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 3: From: "15084252470";tag=as03556fe4 (66) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 4: Call-ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (56) [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 5: CSeq: 103 BYE (13) media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 6: Server: Sippy (13) media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4871 parse_request: Header 7: Content-Length: 0 (17) media1*CLI> --- (8 headers 0 lines) --- media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4630 find_call: = Looking for Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 (Checking To) --From tag as03556fe4 --To-tag 72336e580e055d18f3c0f46c171ddfaa media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:4651 find_call: = Found Their Call ID: 450ebed15fd1505313aceed3254a6618@69.147.177.197 Their Tag 72336e580e055d18f3c0f46c171ddfaa Our tag: as03556fe4 media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:2181 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #28 media1*CLI> [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:2191 __sip_ack: Stopping retransmission on '450ebed15fd1505313aceed3254a6618@69.147.177.197' of Request 103: Match Not Found media1*CLI> Really destroying SIP dialog '450ebed15fd1505313aceed3254a6618@69.147.177.197' Method: INVITE media1*CLI> AGI Rx << GET OPTION /home/porta-um/apache/prompts//en/enter_dest_redial *#1234567890f 9000 media1*CLI> -- Playing '/home/porta-um/apache/prompts//en/enter_dest_redial' (escape_digits=*#1234567890f) (timeout 9000) [Apr 8 15:27:22] WARNING[655]: file.c:626 ast_readaudio_callback: Failed to write frame [Apr 8 15:27:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 8 15:27:22] DEBUG[655]: channel.c:2084 ast_settimeout: Scheduling timer at 0 sample intervals AGI Tx >> 200 result=-1 endpos=52992 media1*CLI> AGI Rx << HANGUP [Apr 8 15:27:22] DEBUG[655]: channel.c:1555 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/69.147.177.196-0815c000' AGI Tx >> 200 result=1 [Apr 8 15:27:22] DEBUG[655]: pbx.c:2411 __ast_pbx_run: Spawn extension (portaum,1A15085323568,2) exited non-zero on 'SIP/69.147.177.196-0815c000' == Spawn extension (portaum, 1A15085323568, 2) exited non-zero on 'SIP/69.147.177.196-0815c000' [Apr 8 15:27:22] DEBUG[655]: channel.c:1555 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/69.147.177.196-0815c000' [Apr 8 15:27:22] DEBUG[655]: channel.c:1767 ast_hangup: Hanging up channel 'SIP/69.147.177.196-0815c000' [Apr 8 15:27:22] DEBUG[655]: chan_sip.c:3507 sip_hangup: Hangup call SIP/69.147.177.196-0815c000, SIP callid 17156d2-c1992d65@75.130.97.187) media1*CLI> [Apr 8 15:27:22] 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:27:22] 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:27:22] DEBUG[655]: chan_sip.c:15886 sip_devicestate: Checking device state for peer 69.147.177.196 media1*CLI> [Apr 8 15:27:22] DEBUG[655]: devicestate.c:287 do_state_change: Changing state for SIP/69.147.177.196 - state 1 (Not in use) media1*CLI> Really destroying SIP dialog '17156d2-c1992d65@75.130.97.187' Method: BYE media1*CLI> exit