[Mar 6 14:19:12] <--- SIP read from 111.111.111.111:5060 ---> INVITE sip:8888888888@222.222.222.222 SIP/2.0 Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK1639cf1c;rport From: "0123456789" ;tag=as09ecd426 To: Contact: Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 06 Mar 2007 19:19:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 308 v=0 o=root 10644 10644 IN IP4 111.111.111.111 s=session c=IN IP4 111.111.111.111 t=0 0 m=audio 12342 RTP/AVP 0 8 3 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - <-------------> [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: INVITE sip:8888888888@222.222.222.222 SIP/2.0 (43) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK1639cf1c;rport (62) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: From: "0123456789" ;tag=as09ecd426 (62) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: To: (34) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Contact: (37) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 (53) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 9: Date: Tue, 06 Mar 2007 19:19:45 GMT (35) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 11: Content-Type: application/sdp (29) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 12: Content-Length: 308 (19) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 13: (0) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: v=0 (3) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: o=root 10644 10644 IN IP4 111.111.111.111 (37) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: s=session (9) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: c=IN IP4 111.111.111.111 (20) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: t=0 0 (5) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: m=audio 12342 RTP/AVP 0 8 3 18 101 (34) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 6 14:19:12] --- (13 headers 14 lines) --- [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:2578 do_setnat: Setting NAT on VRTP to Off [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:2583 do_setnat: Setting NAT on UDPTL to Off [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4308 sip_alloc: Allocating new SIP dialog for 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 - INVITE (With RTP) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:14590 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 6 14:19:12] Sending to 111.111.111.111 : 5060 (NAT) [Mar 6 14:19:12] Using INVITE request as basis request - 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 [Mar 6 14:19:12] Found no matching peer or user for '111.111.111.111:5060' [Mar 6 14:19:12] Found RTP audio format 0 [Mar 6 14:19:12] Found RTP audio format 8 [Mar 6 14:19:12] Found RTP audio format 3 [Mar 6 14:19:12] Found RTP audio format 18 [Mar 6 14:19:12] Found RTP audio format 101 [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4893 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 6 14:19:12] Peer audio RTP is at port 111.111.111.111:12342 [Mar 6 14:19:12] Found description format PCMU for ID 0 [Mar 6 14:19:12] Found description format PCMA for ID 8 [Mar 6 14:19:12] Found description format GSM for ID 3 [Mar 6 14:19:12] Found description format G729 for ID 18 [Mar 6 14:19:12] Got unsupported a:fmtp in SDP offer [Mar 6 14:19:12] Found description format telephone-event for ID 101 [Mar 6 14:19:12] Got unsupported a:fmtp in SDP offer [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:5123 process_sdp: T38 state changed to 0 on channel [Mar 6 14:19:12] Capabilities: us - 0x100 (g729), peer - audio=0x10e (gsm|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x100 (g729) [Mar 6 14:19:12] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 6 14:19:12] Peer audio RTP is at port 111.111.111.111:12342 [Mar 6 14:19:12] Peer video RTP is at port 111.111.111.111:29216 [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:5203 process_sdp: We're settling with these formats: 0x100 (g729) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:13378 handle_request_invite: Checking SIP call limits for device [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call [Mar 6 14:19:12] Looking for 8888888888 in from-external (domain 222.222.222.222) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:3803 sip_new: *** Our native formats are 0x100 (g729) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:3804 sip_new: *** Joint capabilities are 0x100 (g729) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:3805 sip_new: *** Our capabilities are 0x100 (g729) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:3806 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:3829 sip_new: This channel will not be able to handle video. [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:7964 build_route: build_route: Contact hop: [Mar 6 14:19:12] list_route: hop: [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:13453 handle_request_invite: SIP/111.111.111.111-08f66190: New call is still down.... Trying... [Mar 6 14:19:12] <--- Transmitting (NAT) to 111.111.111.111:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK1639cf1c;received=111.111.111.111;rport=5060 From: "0123456789" ;tag=as09ecd426 To: Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 6 14:19:12] DEBUG[25896]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/111.111.111.111-08f66190 [Mar 6 14:19:12] DEBUG[25886]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 111.111.111.111 [Mar 6 14:19:12] DEBUG[25886]: chan_sip.c:15201 sip_devicestate: Checking device state for peer 111.111.111.111 [Mar 6 14:19:12] DEBUG[25886]: devicestate.c:287 do_state_change: Changing state for SIP/111.111.111.111 - state 2 (In use) [Mar 6 14:19:12] DEBUG[25912]: pbx.c:1791 pbx_extension_helper: Launching 'Goto' [Mar 6 14:19:12] -- Executing [8888888888@from-external:1] Goto("SIP/111.111.111.111-08f66190", "a2billing|cc-18888888888|1") in new stack [Mar 6 14:19:12] -- Goto (a2billing,cc-18888888888,1) [Mar 6 14:19:12] DEBUG[25912]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 6 14:19:12] -- Executing [cc-18888888888@a2billing:1] Set("SIP/111.111.111.111-08f66190", "TIMEOUT(absolute)=10800") in new stack [Mar 6 14:19:12] -- Channel will hangup at 2007-03-06 22:19:12 UTC. [Mar 6 14:19:12] DEBUG[25912]: pbx.c:1791 pbx_extension_helper: Launching 'Answer' [Mar 6 14:19:12] -- Executing [cc-18888888888@a2billing:2] Answer("SIP/111.111.111.111-08f66190", "") in new stack [Mar 6 14:19:12] DEBUG[25912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/111.111.111.111-08f66190 [Mar 6 14:19:12] DEBUG[25886]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 111.111.111.111 [Mar 6 14:19:12] DEBUG[25886]: chan_sip.c:15201 sip_devicestate: Checking device state for peer 111.111.111.111 [Mar 6 14:19:12] DEBUG[25886]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x8f7a0e8' [Mar 6 14:19:12] DEBUG[25912]: chan_sip.c:3461 sip_answer: SIP answering channel: SIP/111.111.111.111-08f66190 [Mar 6 14:19:12] DEBUG[25912]: chan_sip.c:6414 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 6 14:19:12] DEBUG[25886]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x8f7a0e8' [Mar 6 14:19:12] DEBUG[25912]: chan_sip.c:6182 add_sdp: ** Our capability: 0x100 (g729) Video flag: True [Mar 6 14:19:12] DEBUG[25912]: chan_sip.c:6183 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 6 14:19:12] DEBUG[25886]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x8f7a0e8' [Mar 6 14:19:12] Audio is at 222.222.222.222 port 14200 [Mar 6 14:19:12] Adding codec 0x100 (g729) to SDP [Mar 6 14:19:12] Adding non-codec 0x1 (telephone-event) to SDP [Mar 6 14:19:12] DEBUG[25886]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x8f7a0e8' [Mar 6 14:19:12] DEBUG[25912]: chan_sip.c:6314 add_sdp: -- Done with adding codecs to SDP [Mar 6 14:19:12] DEBUG[25912]: chan_sip.c:6359 add_sdp: Done building SDP. Settling with this capability: 0x100 (g729) [Mar 6 14:19:12] DEBUG[25886]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x8f7a0e8' [Mar 6 14:19:12] <--- Reliably Transmitting (NAT) to 111.111.111.111:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK1639cf1c;received=111.111.111.111;rport=5060 From: "0123456789" ;tag=as09ecd426 To: ;tag=as56a569bb Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 265 v=0 o=root 25881 25881 IN IP4 222.222.222.222 s=session c=IN IP4 222.222.222.222 t=0 0 m=audio 14200 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 6 14:19:12] DEBUG[25886]: channel.c:1026 channel_find_locked: Avoiding initial deadlock for channel '0x8f7a0e8' [Mar 6 14:19:12] DEBUG[25912]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #221 [Mar 6 14:19:12] DEBUG[25912]: pbx.c:1791 pbx_extension_helper: Launching 'Wait' [Mar 6 14:19:12] DEBUG[25886]: devicestate.c:287 do_state_change: Changing state for SIP/111.111.111.111 - state 2 (In use) [Mar 6 14:19:12] -- Executing [cc-18888888888@a2billing:3] Wait("SIP/111.111.111.111-08f66190", "1") in new stack [Mar 6 14:19:12] <--- SIP read from 111.111.111.111:5060 ---> ACK sip:8888888888@222.222.222.222 SIP/2.0 Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0de8d7a0;rport From: "0123456789" ;tag=as09ecd426 To: ;tag=as56a569bb Contact: Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: ACK sip:8888888888@222.222.222.222 SIP/2.0 (40) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0de8d7a0;rport (62) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: From: "0123456789" ;tag=as09ecd426 (62) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: To: ;tag=as56a569bb (49) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Contact: (37) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 (53) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: CSeq: 102 ACK (13) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 9: Content-Length: 0 (17) [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 10: (0) [Mar 6 14:19:12] --- (10 headers 0 lines) --- [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:14590 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #221 [Mar 6 14:19:12] DEBUG[25896]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111' of Response 102: Match Not Found [Mar 6 14:19:13] DEBUG[25912]: pbx.c:1791 pbx_extension_helper: Launching 'DeadAGI' [Mar 6 14:19:13] -- Executing [cc-18888888888@a2billing:4] DeadAGI("SIP/111.111.111.111-08f66190", "a2billing.php|1") in new stack [Mar 6 14:19:13] -- Launched AGI Script /var/lib/asterisk/agi-bin/a2billing.php [Mar 6 14:19:13] a2billing.php|1: line:58 - IDCONFIG : 1 [Mar 6 14:19:13] a2billing.php|1: [Mar 6 14:19:13] a2billing.php|1: line:67 - MODE : standard [Mar 6 14:19:13] a2billing.php|1: [Mar 6 14:19:13] DEBUG[25912]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to g729 [Mar 6 14:19:13] DEBUG[25912]: rtp.c:2687 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Mar 6 14:19:13] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Mar 6 14:19:13] -- Playing 'prepaid-enter-dest' (language 'en') [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 111.111.111.111 [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 53 (5), at 111.111.111.111 [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 6 14:19:19] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 54 (6), at 111.111.111.111 [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 52 (0), at 111.111.111.111 [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:20] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 111.111.111.111 [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 53 (0), at 111.111.111.111 [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 51 (0), at 111.111.111.111 [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:21] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 52 (0), at 111.111.111.111 [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 56 (0), at 111.111.111.111 [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 111.111.111.111 [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 6 14:19:22] DEBUG[25912]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Mar 6 14:19:22] -- AGI Script Executing Application: (DIAL) Options: (SIP/provider/40256000000|60|rHL(44400000:61000:30000)) [Mar 6 14:19:22] -- Limit Data for this call: [Mar 6 14:19:22] > timelimit = 44400000 [Mar 6 14:19:22] > play_warning = 61000 [Mar 6 14:19:22] > play_to_caller = yes [Mar 6 14:19:22] > play_to_callee = no [Mar 6 14:19:22] > warning_freq = 30000 [Mar 6 14:19:22] > start_sound = (null) [Mar 6 14:19:22] > warning_sound = timeleft [Mar 6 14:19:22] > end_sound = (null) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:15267 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4308 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:2619 create_addr_from_peer: Our T38 capability (3856) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:2583 do_setnat: Setting NAT on UDPTL to Off [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:3803 sip_new: *** Our native formats are 0x100 (g729) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:3804 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:3805 sip_new: *** Our capabilities are 0x100 (g729) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:3806 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:3808 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:3829 sip_new: This channel will not be able to handle video. [Mar 6 14:19:22] DEBUG[25912]: rtp.c:1579 ast_rtp_make_compatible: Seeded SDP of 'SIP/provider-08f837f8' with that of 'SIP/111.111.111.111-08f66190' [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-a2billing-cc-18888888888-4. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-a2billing-cc-18888888888-3. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-a2billing-cc-18888888888-2. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-a2billing-cc-18888888888-1. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-from-external-8888888888-1. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 6 14:19:22] DEBUG[25912]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:2828 sip_call: Outgoing Call for 40256000000 [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:3001 update_call_counter: Updating call counter for outgoing call [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:2843 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:6182 add_sdp: ** Our capability: 0x100 (g729) Video flag: False [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:6183 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 6 14:19:22] Audio is at 222.222.222.222 port 12102 [Mar 6 14:19:22] Adding codec 0x100 (g729) to SDP [Mar 6 14:19:22] Adding non-codec 0x1 (telephone-event) to SDP [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:6314 add_sdp: -- Done with adding codecs to SDP [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:6359 add_sdp: Done building SDP. Settling with this capability: 0x100 (g729) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 0: INVITE sip:40256000000@provider.tel SIP/2.0 (44) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 1: Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK0995ec01;rport (64) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 2: From: "0123456789" ;tag=as56b13d73 (64) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 3: To: (35) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 4: Contact: (39) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 5: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 (55) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 7: User-Agent: Asterisk PBX (18) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 9: Date: Tue, 06 Mar 2007 19:19:22 GMT (35) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 11: Supported: replaces (19) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 13: Content-Length: 265 (19) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4571 parse_request: Header 14: (0) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: v=0 (3) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: o=root 25881 25881 IN IP4 222.222.222.222 (39) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: s=session (9) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: c=IN IP4 222.222.222.222 (22) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: t=0 0 (5) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: m=audio 12102 RTP/AVP 18 101 (28) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: a=ptime:20 (10) [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:4603 parse_request: Line: a=sendrecv (10) [Mar 6 14:19:22] Reliably Transmitting (no NAT) to 213.251.136.62:5060: INVITE sip:40256000000@provider.tel SIP/2.0 Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK0995ec01;rport From: "0123456789" ;tag=as56b13d73 To: Contact: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 06 Mar 2007 19:19:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 25881 25881 IN IP4 222.222.222.222 s=session c=IN IP4 222.222.222.222 t=0 0 m=audio 12102 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 6 14:19:22] DEBUG[25912]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #248 [Mar 6 14:19:22] -- Called provider/40256000000 [Mar 6 14:19:22] DEBUG[25912]: channel.c:2435 ast_indicate_data: Driver for channel 'SIP/111.111.111.111-08f66190' does not support indication 3, emulating it [Mar 6 14:19:22] DEBUG[25912]: channel.c:2845 set_format: Set channel SIP/111.111.111.111-08f66190 to write format slin [Mar 6 14:19:22] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Mar 6 14:19:22] DEBUG[25912]: channel.c:2332 __ast_read: Generator got voice, switching to phase locked mode [Mar 6 14:19:22] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:22] DEBUG[25912]: rtp.c:2540 ast_rtp_raw_write: Difference is 40264, ms is 5053 [Mar 6 14:19:23] <--- SIP read from 213.251.136.62:5060 ---> SIP/2.0 407 Proxy Authentication Required CSeq: 102 INVITE Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK0995ec01;rport From: "0123456789" ;tag=as56b13d73 Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 To: Contact: Proxy-Authenticate: DIGEST realm="VoipSwitch", nonce="117320876306190706503192309210" Content-Length: 0 <-------------> [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: SIP/2.0 407 Proxy Authentication Required (41) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: CSeq: 102 INVITE (16) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK0995ec01;rport (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: From: "0123456789" ;tag=as56b13d73 (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 (55) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: To: (35) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: Contact: (48) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: Proxy-Authenticate: DIGEST realm="VoipSwitch", nonce="117320876306190706503192309210" (85) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: Content-Length: 0 (17) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 9: (0) [Mar 6 14:19:23] --- (9 headers 0 lines) --- [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:2069 __sip_ack: Acked pending invite 102 [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #248 [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' of Request 102: Match Not Found [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:11621 handle_response_invite: SIP response 407 to standard invite [Mar 6 14:19:23] Transmitting (no NAT) to 213.251.136.62:5060: ACK sip:40256000000@provider.tel SIP/2.0 Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK0995ec01;rport From: "0123456789" ;tag=as56b13d73 To: Contact: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:11044 do_proxy_auth: Auth attempt 1 on INVITE [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:6182 add_sdp: ** Our capability: 0x100 (g729) Video flag: False [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:6183 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 6 14:19:23] Audio is at 222.222.222.222 port 12102 [Mar 6 14:19:23] Adding codec 0x100 (g729) to SDP [Mar 6 14:19:23] Adding non-codec 0x1 (telephone-event) to SDP [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:6314 add_sdp: -- Done with adding codecs to SDP [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:6359 add_sdp: Done building SDP. Settling with this capability: 0x100 (g729) [Mar 6 14:19:23] Reliably Transmitting (no NAT) to 213.251.136.62:5060: INVITE sip:40256000000@provider.tel SIP/2.0 Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 To: Contact: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Proxy-Authorization: Digest username="user", realm="VoipSwitch", algorithm=MD5, uri="sip:40256000000@provider.tel", nonce="117320876306190706503192309210", response="f5a68b9415f99aee72ec733e653a9db2", opaque="" Date: Tue, 06 Mar 2007 19:19:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 25881 25882 IN IP4 222.222.222.222 s=session c=IN IP4 222.222.222.222 t=0 0 m=audio 12102 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #250 [Mar 6 14:19:23] <--- SIP read from 213.251.136.62:5060 ---> SIP/2.0 100 Trying CSeq: 103 INVITE Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 To: ;tag=0603190719235122869537237 Contact: Content-Length: 0 <-------------> [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: CSeq: 103 INVITE (16) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: From: "0123456789" ;tag=as56b13d73 (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 (55) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: To: ;tag=0603190719235122869537237 (65) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: Contact: (48) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: Content-Length: 0 (17) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: (0) [Mar 6 14:19:23] --- (8 headers 0 lines) --- [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:2120 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #250 - INVITE (got response) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:2129 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' Request 103: Found [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:11621 handle_response_invite: SIP response 100 to standard invite [Mar 6 14:19:23] <--- SIP read from 213.251.136.62:5060 ---> SIP/2.0 183 Session Progress CSeq: 103 INVITE Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 To: ;tag=0603190719235122869537237 Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=VoipSwitch 8236 8236 IN IP4 213.251.136.62 s=VoipSIP i=Audio Session c=IN IP4 213.251.136.62 t=0 0 m=audio 7236 RTP/AVP 18 101 a=rtpmap:18 G729/8000/1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: CSeq: 103 INVITE (16) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: From: "0123456789" ;tag=as56b13d73 (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 (55) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: To: ;tag=0603190719235122869537237 (65) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: Contact: (48) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: Content-Type: application/sdp (29) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: Content-Length: 217 (19) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 9: (0) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: v=0 (3) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: o=VoipSwitch 8236 8236 IN IP4 213.251.136.62 (44) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: s=VoipSIP (9) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: i=Audio Session (15) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: c=IN IP4 213.251.136.62 (23) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: t=0 0 (5) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: m=audio 7236 RTP/AVP 18 101 (27) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:18 G729/8000/1 (23) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=fmtp:101 0-15 (15) [Mar 6 14:19:23] --- (9 headers 10 lines) --- [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:2129 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' Request 103: Found [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:11621 handle_response_invite: SIP response 183 to standard invite [Mar 6 14:19:23] Found RTP audio format 18 [Mar 6 14:19:23] Found RTP audio format 101 [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4893 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 6 14:19:23] Peer audio RTP is at port 213.251.136.62:7236 [Mar 6 14:19:23] Found description format G729 for ID 18 [Mar 6 14:19:23] Found description format telephone-event for ID 101 [Mar 6 14:19:23] Got unsupported a:fmtp in SDP offer [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:5123 process_sdp: T38 state changed to 0 on channel SIP/provider-08f837f8 [Mar 6 14:19:23] Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Mar 6 14:19:23] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 6 14:19:23] Peer audio RTP is at port 213.251.136.62:7236 [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:5203 process_sdp: We're settling with these formats: 0x100 (g729) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:5210 process_sdp: We have an owner, now see if we need to change this call [Mar 6 14:19:23] <--- SIP read from 213.251.136.62:5060 ---> SIP/2.0 180 Ringing CSeq: 103 INVITE Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 To: ;tag=0603190719235122869537237 Contact: Content-Type: application/sdp Content-Length: 217 v=0 o=VoipSwitch 8236 8236 IN IP4 213.251.136.62 s=VoipSIP i=Audio Session c=IN IP4 213.251.136.62 t=0 0 m=audio 7236 RTP/AVP 18 101 a=rtpmap:18 G729/8000/1 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Mar 6 14:19:23] -- Call on SIP/provider-08f837f8 left from hold [Mar 6 14:19:23] DEBUG[25912]: channel.c:2845 set_format: Set channel SIP/111.111.111.111-08f66190 to write format g729 [Mar 6 14:19:23] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:23] -- SIP/provider-08f837f8 is making progress passing it to SIP/111.111.111.111-08f66190 [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: CSeq: 103 INVITE (16) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: From: "0123456789" ;tag=as56b13d73 (64) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 (55) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: To: ;tag=0603190719235122869537237 (65) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: Contact: (48) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: Content-Type: application/sdp (29) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: Content-Length: 217 (19) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 9: (0) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: v=0 (3) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: o=VoipSwitch 8236 8236 IN IP4 213.251.136.62 (44) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: s=VoipSIP (9) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: i=Audio Session (15) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: c=IN IP4 213.251.136.62 (23) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: t=0 0 (5) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: m=audio 7236 RTP/AVP 18 101 (27) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:18 G729/8000/1 (23) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4603 parse_request: Line: a=fmtp:101 0-15 (15) [Mar 6 14:19:23] --- (9 headers 10 lines) --- [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:2129 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' Request 103: Found [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:11621 handle_response_invite: SIP response 180 to standard invite [Mar 6 14:19:23] DEBUG[25896]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/provider-08f837f8 [Mar 6 14:19:23] DEBUG[25886]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - provider [Mar 6 14:19:23] DEBUG[25886]: chan_sip.c:15201 sip_devicestate: Checking device state for peer provider [Mar 6 14:19:23] DEBUG[25886]: devicestate.c:287 do_state_change: Changing state for SIP/provider - state 1 (Not in use) [Mar 6 14:19:23] Found RTP audio format 18 [Mar 6 14:19:23] Found RTP audio format 101 [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:4893 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 6 14:19:23] Peer audio RTP is at port 213.251.136.62:7236 [Mar 6 14:19:23] Found description format G729 for ID 18 [Mar 6 14:19:23] Found description format telephone-event for ID 101 [Mar 6 14:19:23] Got unsupported a:fmtp in SDP offer [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:5123 process_sdp: T38 state changed to 0 on channel SIP/provider-08f837f8 [Mar 6 14:19:23] Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Mar 6 14:19:23] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 6 14:19:23] Peer audio RTP is at port 213.251.136.62:7236 [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:5203 process_sdp: We're settling with these formats: 0x100 (g729) [Mar 6 14:19:23] DEBUG[25896]: chan_sip.c:5210 process_sdp: We have an owner, now see if we need to change this call [Mar 6 14:19:23] -- SIP/provider-08f837f8 is ringing [Mar 6 14:19:23] -- Call on SIP/provider-08f837f8 left from hold [Mar 6 14:19:23] -- SIP/provider-08f837f8 is making progress passing it to SIP/111.111.111.111-08f66190 [Mar 6 14:19:24] [Mar 6 14:19:25] DEBUG[25912]: rtp.c:871 ast_rtcp_read: Got RTCP report of 32 bytes [Mar 6 14:19:25] WARNING[25912]: rtp.c:883 ast_rtcp_read: RTCP Read too short [Mar 6 14:19:28] DEBUG[25912]: rtp.c:871 ast_rtcp_read: Got RTCP report of 32 bytes [Mar 6 14:19:28] WARNING[25912]: rtp.c:883 ast_rtcp_read: RTCP Read too short [Mar 6 14:19:31] <--- SIP read from 111.111.111.111:5060 ---> BYE sip:8888888888@222.222.222.222 SIP/2.0 Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK662cc582;rport From: "0123456789" ;tag=as09ecd426 To: ;tag=as56a569bb Contact: Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: BYE sip:8888888888@222.222.222.222 SIP/2.0 (40) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK662cc582;rport (62) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: From: "0123456789" ;tag=as09ecd426 (62) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: To: ;tag=as56a569bb (49) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Contact: (37) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 (53) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: CSeq: 103 BYE (13) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 9: Content-Length: 0 (17) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 10: (0) [Mar 6 14:19:31] --- (10 headers 0 lines) --- [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:14590 handle_request: **** Received BYE (8) - Command in SIP BYE [Mar 6 14:19:31] Sending to 111.111.111.111 : 5060 (NAT) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:1631 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:14167 handle_request_bye: Received bye, issuing owner hangup [Mar 6 14:19:31] <--- Transmitting (NAT) to 111.111.111.111:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK662cc582;received=111.111.111.111;rport=5060 From: "0123456789" ;tag=as09ecd426 To: ;tag=as56a569bb Call-ID: 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 6 14:19:31] DEBUG[25912]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 6 14:19:31] DEBUG[25912]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/provider-08f837f8' [Mar 6 14:19:31] DEBUG[25912]: chan_sip.c:3310 sip_hangup: Hangup call SIP/provider-08f837f8, SIP callid 47f47b71605689927ba0ebaa15659a3f@222.222.222.222) [Mar 6 14:19:31] DEBUG[25912]: chan_sip.c:3333 sip_hangup: Hanging up channel in state Ringing (not UP) [Mar 6 14:19:31] Scheduling destruction of SIP dialog '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' in 32000 ms (Method: INVITE) [Mar 6 14:19:31] DEBUG[25912]: chan_sip.c:2069 __sip_ack: Acked pending invite 103 [Mar 6 14:19:31] DEBUG[25912]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' of Request 103: Match Not Found [Mar 6 14:19:31] Reliably Transmitting (no NAT) to 213.251.136.62:5060: CANCEL sip:40256000000@provider.tel SIP/2.0 Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 To: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 CSeq: 103 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 6 14:19:31] DEBUG[25912]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #267 [Mar 6 14:19:31] Scheduling destruction of SIP dialog '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' in 32000 ms (Method: INVITE) [Mar 6 14:19:31] DEBUG[25912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/provider-08f837f8 [Mar 6 14:19:31] DEBUG[25912]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Mar 6 14:19:31] DEBUG[25886]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - provider [Mar 6 14:19:31] DEBUG[25886]: chan_sip.c:15201 sip_devicestate: Checking device state for peer provider [Mar 6 14:19:31] DEBUG[25886]: devicestate.c:287 do_state_change: Changing state for SIP/provider - state 1 (Not in use) [Mar 6 14:19:31] a2billing.php|1: [Class.RateEngine.php:900] DIAL SIP/provider/40256000000, DIALSTATUS = 'CANCEL', HANGUPCAUSE = 0, ANSWERTIME = [Mar 6 14:19:31] WARNING[25912]: file.c:616 ast_readaudio_callback: Failed to write frame [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] -- Playing 'prepaid-enter-dest' (language 'en') [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] -- Playing 'prepaid-invalid-digits' (escape_digits=#) (sample_offset 0) [Mar 6 14:19:31] WARNING[25912]: file.c:616 ast_readaudio_callback: Failed to write frame [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] WARNING[25912]: file.c:616 ast_readaudio_callback: Failed to write frame [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] -- Playing 'prepaid-enter-dest' (language 'en') [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] -- Playing 'prepaid-invalid-digits' (escape_digits=#) (sample_offset 0) [Mar 6 14:19:31] WARNING[25912]: file.c:616 ast_readaudio_callback: Failed to write frame [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] WARNING[25912]: file.c:616 ast_readaudio_callback: Failed to write frame [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] -- Playing 'prepaid-enter-dest' (language 'en') [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] -- Playing 'prepaid-invalid-digits' (escape_digits=#) (sample_offset 0) [Mar 6 14:19:31] WARNING[25912]: file.c:616 ast_readaudio_callback: Failed to write frame [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] DEBUG[25912]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 6 14:19:31] DEBUG[25912]: channel.c:1480 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/111.111.111.111-08f66190' [Mar 6 14:19:31] -- AGI Script a2billing.php completed, returning -1 Huh? Child handler, but nobody there? [Mar 6 14:19:31] DEBUG[25912]: pbx.c:2410 __ast_pbx_run: Extension cc-18888888888, priority 4 returned normally even though call was hung up [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '"0123456789" <0123456789>' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '0123456789' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'cc-18888888888' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'a2billing' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/111.111.111.111-08f66190' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/provider-08f837f8' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'Dial' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/provider/40256000000|60|rHL(44400000:61000:30000)' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-06 14:19:12' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-06 14:19:12' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-06 14:19:31' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '19' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '19' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '1173208752.0' [Mar 6 14:19:31] DEBUG[25912]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 6 14:19:31] DEBUG[25912]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/111.111.111.111-08f66190' [Mar 6 14:19:31] DEBUG[25912]: chan_sip.c:3310 sip_hangup: Hangup call SIP/111.111.111.111-08f66190, SIP callid 5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111) [Mar 6 14:19:31] DEBUG[25912]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/111.111.111.111-08f66190 [Mar 6 14:19:31] DEBUG[25886]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 111.111.111.111 [Mar 6 14:19:31] DEBUG[25886]: chan_sip.c:15201 sip_devicestate: Checking device state for peer 111.111.111.111 [Mar 6 14:19:31] DEBUG[25886]: devicestate.c:287 do_state_change: Changing state for SIP/111.111.111.111 - state 1 (Not in use) [Mar 6 14:19:31] <--- SIP read from 213.251.136.62:5060 ---> SIP/2.0 200 OK CSeq: 103 CANCEL Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 To: ;tag=0603190719235122869537237 Contact: Content-Length: 0 <-------------> [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: CSeq: 103 CANCEL (16) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport (64) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: From: "0123456789" ;tag=as56b13d73 (64) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 (55) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: To: ;tag=0603190719235122869537237 (65) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: Contact: (48) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: Content-Length: 0 (17) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: (0) [Mar 6 14:19:31] --- (8 headers 0 lines) --- [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #267 [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' of Request 103: Match Not Found [Mar 6 14:19:31] Really destroying SIP dialog '5acaaa8c2eb2f8b035e2789c6818bf2b@111.111.111.111' Method: BYE [Mar 6 14:19:31] <--- SIP read from 213.251.136.62:5060 ---> SIP/2.0 487 Request Terminated CSeq: 103 INVITE Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 To: ;tag=0603190719235122869537237 Contact: Content-Length: 0 <-------------> [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 1: CSeq: 103 INVITE (16) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 2: Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport (64) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 3: From: "0123456789" ;tag=as56b13d73 (64) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 4: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 (55) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 5: To: ;tag=0603190719235122869537237 (65) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 6: Contact: (48) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 7: Content-Length: 0 (17) [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:4571 parse_request: Header 8: (0) [Mar 6 14:19:31] --- (8 headers 0 lines) --- [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '47f47b71605689927ba0ebaa15659a3f@222.222.222.222' of Request 103: Match Found [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:11621 handle_response_invite: SIP response 487 to standard invite [Mar 6 14:19:31] Transmitting (no NAT) to 213.251.136.62:5060: ACK sip:40256000000@provider.tel SIP/2.0 Via: SIP/2.0/UDP 222.222.222.222:5060;branch=z9hG4bK13aa3604;rport From: "0123456789" ;tag=as56b13d73 To: ;tag=0603190719235122869537237 Contact: Call-ID: 47f47b71605689927ba0ebaa15659a3f@222.222.222.222 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 6 14:19:31] DEBUG[25896]: chan_sip.c:3001 update_call_counter: Updating call counter for outgoing call