ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> ASTEISK05*CLI> [Mar 15 17:11:07] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:07] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:08] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'login' [Mar 15 17:11:08] == Parsing '/etc/asterisk/manager.conf': [Mar 15 17:11:08] DEBUG[14886]: config.c:851 config_text_file_load: Parsing /etc/asterisk/manager.conf [Mar 15 17:11:08] Found [Mar 15 17:11:08] DEBUG[14886]: acl.c:200 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer [Mar 15 17:11:08] DEBUG[14886]: acl.c:215 ast_apply_ha: ##### Testing 167.206.178.8 with 0.0.0.0 [Mar 15 17:11:08] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:10] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:10] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:11] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:11] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:14] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:14] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:15] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:15] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:18] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:18] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:19] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:19] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:19] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:19] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:19] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:19] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:20] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:20] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:22] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:22] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:23] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:23] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:66.63.165.151 SIP/2.0 (33) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK2ab28b49;rport (64) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as3101ab93 (60) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (23) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Contact: (37) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 5df40537039c130400fe52c92919280b@167.206.178.7 (55) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 15 Mar 2007 21:11:23 GMT (35) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Mar 15 17:11:23] Reliably Transmitting (no NAT) to 66.63.165.151:5060: OPTIONS sip:66.63.165.151 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK2ab28b49;rport From: "asterisk" ;tag=as3101ab93 To: Contact: Call-ID: 5df40537039c130400fe52c92919280b@167.206.178.7 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 15 Mar 2007 21:11:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38762 [Mar 15 17:11:23] <--- SIP read from 66.63.165.151:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK2ab28b49;rport=5060 From: "asterisk" ;tag=as3101ab93 To: ;tag=0-tdb3221212128 Call-ID: 5df40537039c130400fe52c92919280b@167.206.178.7 CSeq: 102 OPTIONS Server: Sansay VSX 2.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE Content-Length: 0 <-------------> [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK2ab28b49;rport=5060 (69) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as3101ab93 (60) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=0-tdb3221212128 (43) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 5df40537039c130400fe52c92919280b@167.206.178.7 (55) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: Server: Sansay VSX 2.1 (22) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE (40) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Content-Length: 0 (17) [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 15 17:11:23] --- (9 headers 0 lines) --- [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38762 [Mar 15 17:11:23] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5df40537039c130400fe52c92919280b@167.206.178.7' of Request 102: Match Not Found [Mar 15 17:11:23] Really destroying SIP dialog '5df40537039c130400fe52c92919280b@167.206.178.7' Method: OPTIONS [Mar 15 17:11:24] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:24] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:26] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:26] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:27] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:27] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:28] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Originate' [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:15306 sip_request_call: Asked to create a SIP channel with formats: 0x40 (slin) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 15 17:11:28] RTP-stats [Mar 15 17:11:28] * Our Receiver: [Mar 15 17:11:28] SSRC: 0 [Mar 15 17:11:28] Received packets: 0 [Mar 15 17:11:28] Lost packets: 0 [Mar 15 17:11:28] Jitter: 0.0000 [Mar 15 17:11:28] Transit: 0.0000 [Mar 15 17:11:28] RR-count: 0 [Mar 15 17:11:28] * Our Sender: [Mar 15 17:11:28] SSRC: 316346379 [Mar 15 17:11:28] Sent packets: 0 [Mar 15 17:11:28] Lost packets: 0 [Mar 15 17:11:28] Jitter: 0 [Mar 15 17:11:28] SR-count: 0 [Mar 15 17:11:28] RTT: 0.000000 [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x4 (ulaw) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x40 (slin) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:2830 sip_call: Outgoing Call for 16173958126 [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:6188 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x40 (slin) [Mar 15 17:11:28] Audio is at 167.206.178.7 port 15292 [Mar 15 17:11:28] Adding codec 0x4 (ulaw) to SDP [Mar 15 17:11:28] Adding non-codec 0x1 (telephone-event) to SDP [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:16173958126@69.16.233.35 SIP/2.0 (43) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;rport (64) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 2: From: "6025161069" ;tag=as3f5c9eac (64) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 3: To: (34) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 4: Contact: (39) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 (55) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 15 Mar 2007 21:11:28 GMT (35) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 242 (19) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: o=root 27616 27616 IN IP4 167.206.178.7 (39) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: c=IN IP4 167.206.178.7 (22) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: m=audio 15292 RTP/AVP 0 101 (27) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 15 17:11:28] Reliably Transmitting (no NAT) to 69.16.233.35:5060: INVITE sip:16173958126@69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;rport From: "6025161069" ;tag=as3f5c9eac To: Contact: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 15 Mar 2007 21:11:28 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 242 v=0 o=root 27616 27616 IN IP4 167.206.178.7 s=session c=IN IP4 167.206.178.7 t=0 0 m=audio 15292 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 15 17:11:28] DEBUG[14888]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38765 [Mar 15 17:11:28] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:28] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;received=167.206.178.7;rport=5060 From: "6025161069" ;tag=as3f5c9eac To: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 <-------------> [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;received=167.206.178.7;rport=5060 (92) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "6025161069" ;tag=as3f5c9eac (64) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (34) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 (55) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Contact: (39) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: (0) [Mar 15 17:11:28] --- (10 headers 0 lines) --- [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #38765 - INVITE (got response) [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '05df7a19320d5ecf4e35ca5039941b88@167.206.178.7' Request 102: Found [Mar 15 17:11:28] DEBUG[10175]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite [Mar 15 17:11:28] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:30] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:11:30] DEBUG[31834]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:11:30] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:30] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:30] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;received=167.206.178.7;rport=5060 From: "6025161069" ;tag=as3f5c9eac To: ;tag=as0de4c6d7 Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 216 v=0 o=root 22129 22129 IN IP4 69.16.233.35 s=session c=IN IP4 69.16.233.35 t=0 0 m=audio 15754 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - <-------------> [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;received=167.206.178.7;rport=5060 (92) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "6025161069" ;tag=as3f5c9eac (64) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=as0de4c6d7 (49) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 (55) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Contact: (39) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Content-Length: 216 (19) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: (0) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: o=root 22129 22129 IN IP4 69.16.233.35 (38) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: c=IN IP4 69.16.233.35 (21) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: m=audio 15754 RTP/AVP 0 101 (27) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 15 17:11:30] --- (11 headers 10 lines) --- [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '05df7a19320d5ecf4e35ca5039941b88@167.206.178.7' Request 102: Found [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:11641 handle_response_invite: SIP response 183 to standard invite [Mar 15 17:11:30] Found RTP audio format 0 [Mar 15 17:11:30] Found RTP audio format 101 [Mar 15 17:11:30] Peer audio RTP is at port 69.16.233.35:15754 [Mar 15 17:11:30] Found description format PCMU for ID 0 [Mar 15 17:11:30] Found description format telephone-event for ID 101 [Mar 15 17:11:30] Got unsupported a:fmtp in SDP offer [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/voipjet-00718ab0 [Mar 15 17:11:30] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Mar 15 17:11:30] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 15 17:11:30] Peer audio RTP is at port 69.16.233.35:15754 [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Mar 15 17:11:30] DEBUG[10175]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 15 17:11:31] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:11:31] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:31] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:32] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:32] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:34] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:34] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:35] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:35] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:36] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:36] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:69.16.233.35 SIP/2.0 (32) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK25fef07c;rport (64) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as5ecbf914 (60) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (22) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Contact: (37) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 23a839ef6e489b584b5620d50a05067b@167.206.178.7 (55) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 15 Mar 2007 21:11:37 GMT (35) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Mar 15 17:11:37] Reliably Transmitting (no NAT) to 69.16.233.35:5060: OPTIONS sip:69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK25fef07c;rport From: "asterisk" ;tag=as5ecbf914 To: Contact: Call-ID: 23a839ef6e489b584b5620d50a05067b@167.206.178.7 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 15 Mar 2007 21:11:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38768 [Mar 15 17:11:37] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK25fef07c;received=167.206.178.7;rport=5060 From: "asterisk" ;tag=as5ecbf914 To: ;tag=as15ceec6c Call-ID: 23a839ef6e489b584b5620d50a05067b@167.206.178.7 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Accept: application/sdp Content-Length: 0 <-------------> [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 404 Not Found (21) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK25fef07c;received=167.206.178.7;rport=5060 (92) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as5ecbf914 (60) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=as15ceec6c (37) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 23a839ef6e489b584b5620d50a05067b@167.206.178.7 (55) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Accept: application/sdp (23) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: (0) [Mar 15 17:11:37] --- (10 headers 0 lines) --- [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38768 [Mar 15 17:11:37] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '23a839ef6e489b584b5620d50a05067b@167.206.178.7' of Request 102: Match Not Found [Mar 15 17:11:37] Really destroying SIP dialog '23a839ef6e489b584b5620d50a05067b@167.206.178.7' Method: OPTIONS [Mar 15 17:11:38] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:38] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:38] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;received=167.206.178.7;rport=5060 From: "6025161069" ;tag=as3f5c9eac To: ;tag=as0de4c6d7 Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 216 v=0 o=root 22129 22130 IN IP4 69.16.233.35 s=session c=IN IP4 69.16.233.35 t=0 0 m=audio 15754 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - <-------------> [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK5c893d7d;received=167.206.178.7;rport=5060 (92) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "6025161069" ;tag=as3f5c9eac (64) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=as0de4c6d7 (49) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 (55) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Contact: (39) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Content-Length: 216 (19) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: (0) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: o=root 22129 22130 IN IP4 69.16.233.35 (38) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: c=IN IP4 69.16.233.35 (21) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: m=audio 15754 RTP/AVP 0 101 (27) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 15 17:11:38] --- (11 headers 10 lines) --- [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '05df7a19320d5ecf4e35ca5039941b88@167.206.178.7' of Request 102: Match Not Found [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:11641 handle_response_invite: SIP response 200 to standard invite [Mar 15 17:11:38] Found RTP audio format 0 [Mar 15 17:11:38] Found RTP audio format 101 [Mar 15 17:11:38] Peer audio RTP is at port 69.16.233.35:15754 [Mar 15 17:11:38] Found description format PCMU for ID 0 [Mar 15 17:11:38] Found description format telephone-event for ID 101 [Mar 15 17:11:38] Got unsupported a:fmtp in SDP offer [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/voipjet-00718ab0 [Mar 15 17:11:38] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Mar 15 17:11:38] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 15 17:11:38] Peer audio RTP is at port 69.16.233.35:15754 [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:7980 build_route: build_route: Contact hop: [Mar 15 17:11:38] list_route: hop: [Mar 15 17:11:38] DEBUG[10175]: chan_sip.c:5643 reqprep: Strict routing enforced for session 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 [Mar 15 17:11:38] set_destination: Parsing for address/port to send to [Mar 15 17:11:38] set_destination: set destination to 69.16.233.35, port 5060 [Mar 15 17:11:38] Transmitting (no NAT) to 69.16.233.35:5060: ACK sip:16173958126@69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK2b4a574a;rport From: "6025161069" ;tag=as3f5c9eac To: ;tag=as0de4c6d7 Contact: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 15 17:11:38] DEBUG[14888]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/voipjet-00718ab0 [Mar 15 17:11:38] > Channel SIP/voipjet-00718ab0 was answered. [Mar 15 17:11:38] DEBUG[10171]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - voipjet [Mar 15 17:11:38] DEBUG[10171]: chan_sip.c:15240 sip_devicestate: Checking device state for peer voipjet [Mar 15 17:11:38] DEBUG[10171]: devicestate.c:287 do_state_change: Changing state for SIP/voipjet - state 1 (Not in use) [Mar 15 17:11:38] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Answer' [Mar 15 17:11:38] -- Executing [s@liveonly:1] Answer("SIP/voipjet-00718ab0", "") in new stack [Mar 15 17:11:38] DEBUG[14891]: app_queue.c:546 changethread: Device 'SIP/voipjet' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 15 17:11:38] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' [Mar 15 17:11:38] -- Executing [s@liveonly:2] NoOp("SIP/voipjet-00718ab0", "liveonly message:/var/lib/asterisk/sounds/sound26 M2: M3:3 DID:6234928468 phonenumber:6173958126 Campaign ID:484 CALLERID: ") in new stack [Mar 15 17:11:38] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Wait' [Mar 15 17:11:38] -- Executing [s@liveonly:3] Wait("SIP/voipjet-00718ab0", "1") in new stack [Mar 15 17:11:39] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:39] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:40] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '20070315171140' [Mar 15 17:11:40] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:11:40] -- Executing [s@liveonly:4] Set("SIP/voipjet-00718ab0", "soundfile=DEBUG-20070315171140-1173993088.57.wav") in new stack [Mar 15 17:11:40] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' [Mar 15 17:11:40] -- Executing [s@liveonly:5] NoOp("SIP/voipjet-00718ab0", "DEBUG-20070315171140-1173993088.57.wav") in new stack [Mar 15 17:11:40] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:11:40] -- Executing [s@liveonly:6] Set("SIP/voipjet-00718ab0", "CDR(accountcode)=484") in new stack [Mar 15 17:11:40] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:11:40] -- Executing [s@liveonly:7] Set("SIP/voipjet-00718ab0", "CDR(userfield)= 6173958126") in new stack [Mar 15 17:11:40] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' [Mar 15 17:11:40] -- Executing [s@liveonly:8] NoOp("SIP/voipjet-00718ab0", "machinedetect") in new stack [Mar 15 17:11:40] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'AMD' [Mar 15 17:11:40] -- Executing [s@liveonly:9] AMD("SIP/voipjet-00718ab0", "") in new stack [Mar 15 17:11:40] -- AMD: SIP/voipjet-00718ab0 6025161069 (null) (Fmt: 4) [Mar 15 17:11:40] DEBUG[14890]: app_amd.c:155 isAnsweringMachine: AMD using the default parameters. [Mar 15 17:11:40] -- AMD: initialSilence [5700] greeting [2500] afterGreetingSilence [1200] totalAnalysisTime [6000] minimumWordLength [100] betweenWordsSilence [50] maximumNumberOfWords [4] silenceThreshold [860] [Mar 15 17:11:40] DEBUG[14890]: channel.c:2845 set_format: Set channel SIP/voipjet-00718ab0 to read format slin [Mar 15 17:11:40] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:40] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:40] -- AMD: Word detected. iWordsCount:1 [Mar 15 17:11:40] -- AMD: Changed state to STATE_IN_SILENCE [Mar 15 17:11:41] -- AMD: HUMAN: silenceDuration:1200 afterGreetingSilence:1200 [Mar 15 17:11:41] DEBUG[14890]: channel.c:2845 set_format: Set channel SIP/voipjet-00718ab0 to read format ulaw [Mar 15 17:11:41] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' [Mar 15 17:11:41] -- Executing [s@liveonly:10] NoOp("SIP/voipjet-00718ab0", "AMD got: HUMAN-1200-1200") in new stack [Mar 15 17:11:41] DEBUG[14890]: pbx.c:1712 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 15 17:11:41] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'GotoIf' [Mar 15 17:11:41] -- Executing [s@liveonly:11] GotoIf("SIP/voipjet-00718ab0", "0?liveonly-amd|s|1") in new stack [Mar 15 17:11:41] DEBUG[14890]: pbx.c:5970 pbx_builtin_gotoif: Not taking any branch [Mar 15 17:11:41] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Goto' [Mar 15 17:11:41] -- Executing [s@liveonly:12] Goto("SIP/voipjet-00718ab0", "liveonly-live|s|1") in new stack [Mar 15 17:11:41] -- Goto (liveonly-live,s,1) [Mar 15 17:11:41] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'BackGround' [Mar 15 17:11:41] -- Executing [s@liveonly-live:1] BackGround("SIP/voipjet-00718ab0", "/var/lib/asterisk/sounds/sound26") in new stack [Mar 15 17:11:41] DEBUG[14890]: channel.c:2845 set_format: Set channel SIP/voipjet-00718ab0 to write format slin [Mar 15 17:11:41] DEBUG[14890]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to ulaw [Mar 15 17:11:41] DEBUG[14890]: rtp.c:2706 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Mar 15 17:11:41] DEBUG[14890]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Mar 15 17:11:41] -- Playing '/var/lib/asterisk/sounds/sound26' (language 'en') [Mar 15 17:11:42] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:42] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:43] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:43] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:44] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:44] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:45] DEBUG[14890]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Mar 15 17:11:45] DEBUG[14890]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 69.16.233.35 [Mar 15 17:11:45] DEBUG[14890]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Mar 15 17:11:45] DEBUG[14890]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Mar 15 17:11:45] DEBUG[14890]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Mar 15 17:11:45] DEBUG[14890]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 69.16.233.35 [Mar 15 17:11:45] DEBUG[14890]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 15 17:11:45] DEBUG[14890]: channel.c:2845 set_format: Set channel SIP/voipjet-00718ab0 to write format ulaw [Mar 15 17:11:45] DEBUG[14890]: pbx.c:2374 __ast_pbx_run: Oooh, got something to jump out with ('1')! [Mar 15 17:11:45] == CDR updated on SIP/voipjet-00718ab0 [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' [Mar 15 17:11:45] -- Executing [1@liveonly-live:1] NoOp("SIP/voipjet-00718ab0", "Press 1 transfer") in new stack [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Goto' [Mar 15 17:11:45] -- Executing [1@liveonly-live:2] Goto("SIP/voipjet-00718ab0", "liveonly-transfer|s|1") in new stack [Mar 15 17:11:45] -- Goto (liveonly-transfer,s,1) [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '20070315171145' [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:11:45] -- Executing [s@liveonly-transfer:1] Set("SIP/voipjet-00718ab0", "soundfile=20070315171145-1173993088.57.ulaw") in new stack [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'MixMonitor' [Mar 15 17:11:45] -- Executing [s@liveonly-transfer:2] MixMonitor("SIP/voipjet-00718ab0", "20070315171145-1173993088.57.ulaw|b") in new stack [Mar 15 17:11:45] DEBUG[14890]: channel.c:1348 ast_channel_spy_add: Spy MixMonitor added to channel SIP/voipjet-00718ab0 [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:11:45] -- Executing [s@liveonly-transfer:3] Set("SIP/voipjet-00718ab0", "CALLERID(num)=6234928468") in new stack [Mar 15 17:11:45] == Begin MixMonitor Recording SIP/voipjet-00718ab0 [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1712 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'ExecIf' [Mar 15 17:11:45] -- Executing [s@liveonly-transfer:4] ExecIf("SIP/voipjet-00718ab0", "0|Set|CALLERID(num)=6173958126") in new stack [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-15 17:11:45' [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:11:45] -- Executing [s@liveonly-transfer:5] Set("SIP/voipjet-00718ab0", "CDR(userfield5)=2007-03-15 17:11:45") in new stack [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1712 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'GotoIf' [Mar 15 17:11:45] -- Executing [s@liveonly-transfer:6] GotoIf("SIP/voipjet-00718ab0", "0?20") in new stack [Mar 15 17:11:45] DEBUG[14890]: pbx.c:5970 pbx_builtin_gotoif: Not taking any branch [Mar 15 17:11:45] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Dial' [Mar 15 17:11:45] -- Executing [s@liveonly-transfer:7] Dial("SIP/voipjet-00718ab0", "SIP/16234928468@voipjet||ojm(trans3)") in new stack [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:15306 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 15 17:11:45] RTP-stats [Mar 15 17:11:45] * Our Receiver: [Mar 15 17:11:45] SSRC: 0 [Mar 15 17:11:45] Received packets: 0 [Mar 15 17:11:45] Lost packets: 0 [Mar 15 17:11:45] Jitter: 0.0000 [Mar 15 17:11:45] Transit: 0.0000 [Mar 15 17:11:45] RR-count: 0 [Mar 15 17:11:45] * Our Sender: [Mar 15 17:11:45] SSRC: 1323080237 [Mar 15 17:11:45] Sent packets: 0 [Mar 15 17:11:45] Lost packets: 0 [Mar 15 17:11:45] Jitter: 0 [Mar 15 17:11:45] SR-count: 0 [Mar 15 17:11:45] RTT: 0.000000 [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x4 (ulaw) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-transfer-s-7. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-transfer-s-6. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-transfer-s-5. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-transfer-s-4. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-transfer-s-3. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-transfer-s-2. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable soundfile. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-transfer-s-1. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-live-1-2. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-live-1-1. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-live-s-1. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-12. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-11. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-10. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable AMDCAUSE. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable AMDSTATUS. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-9. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-8. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-7. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-6. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-5. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-4. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-3. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-2. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-liveonly-s-1. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable did. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable message. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable message2. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable message3. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable campaign. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable phonenumber. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable recordid. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable maxcalls. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable transferclid. [Mar 15 17:11:45] DEBUG[14890]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:2830 sip_call: Outgoing Call for 16234928468 [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:6188 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 15 17:11:45] Audio is at 167.206.178.7 port 15698 [Mar 15 17:11:45] Adding codec 0x4 (ulaw) to SDP [Mar 15 17:11:45] Adding non-codec 0x1 (telephone-event) to SDP [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:16234928468@69.16.233.35 SIP/2.0 (43) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;rport (64) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 2: From: "6234928468" ;tag=as21926c7d (64) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 3: To: (34) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 4: Contact: (39) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 (55) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 15 Mar 2007 21:11:45 GMT (35) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 242 (19) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: o=root 27616 27616 IN IP4 167.206.178.7 (39) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: c=IN IP4 167.206.178.7 (22) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: m=audio 15698 RTP/AVP 0 101 (27) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 15 17:11:45] Reliably Transmitting (no NAT) to 69.16.233.35:5060: INVITE sip:16234928468@69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;rport From: "6234928468" ;tag=as21926c7d To: Contact: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 15 Mar 2007 21:11:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 242 v=0 o=root 27616 27616 IN IP4 167.206.178.7 s=session c=IN IP4 167.206.178.7 t=0 0 m=audio 15698 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 15 17:11:45] DEBUG[14890]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38771 [Mar 15 17:11:45] -- Called 16234928468@voipjet [Mar 15 17:11:45] -- Started music on hold, class 'trans3', on SIP/voipjet-00718ab0 [Mar 15 17:11:45] DEBUG[14890]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Mar 15 17:11:45] DEBUG[14890]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Mar 15 17:11:45] DEBUG[14890]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Mar 15 17:11:45] DEBUG[14890]: channel.c:1531 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/voipjet-00718ab0 [Mar 15 17:11:45] DEBUG[14890]: channel.c:2332 __ast_read: Generator got voice, switching to phase locked mode [Mar 15 17:11:45] DEBUG[14890]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 15 17:11:45] DEBUG[14890]: res_musiconhold.c:254 ast_moh_files_next: SIP/voipjet-00718ab0 Opened file 0 '/var/lib/asterisk/moh/trans3/trans3' [Mar 15 17:11:45] DEBUG[14890]: channel.c:1531 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/voipjet-00718ab0 [Mar 15 17:11:45] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;received=167.206.178.7;rport=5060 From: "6234928468" ;tag=as21926c7d To: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 <-------------> [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;received=167.206.178.7;rport=5060 (92) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "6234928468" ;tag=as21926c7d (64) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (34) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 (55) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Contact: (39) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: (0) [Mar 15 17:11:45] --- (10 headers 0 lines) --- [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #38771 - INVITE (got response) [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '52b9373d378a87ee5f281b192acea28f@167.206.178.7' Request 102: Found [Mar 15 17:11:45] DEBUG[10175]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite [Mar 15 17:11:46] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:46] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:47] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:47] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:47] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;received=167.206.178.7;rport=5060 From: "6234928468" ;tag=as21926c7d To: ;tag=as7316cb62 Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 216 v=0 o=root 22129 22129 IN IP4 69.16.233.35 s=session c=IN IP4 69.16.233.35 t=0 0 m=audio 13410 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - <-------------> [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;received=167.206.178.7;rport=5060 (92) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "6234928468" ;tag=as21926c7d (64) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=as7316cb62 (49) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 (55) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Contact: (39) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Content-Length: 216 (19) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: (0) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: o=root 22129 22129 IN IP4 69.16.233.35 (38) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: c=IN IP4 69.16.233.35 (21) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: m=audio 13410 RTP/AVP 0 101 (27) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 15 17:11:47] --- (11 headers 10 lines) --- [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '52b9373d378a87ee5f281b192acea28f@167.206.178.7' Request 102: Found [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:11641 handle_response_invite: SIP response 183 to standard invite [Mar 15 17:11:47] Found RTP audio format 0 [Mar 15 17:11:47] Found RTP audio format 101 [Mar 15 17:11:47] Peer audio RTP is at port 69.16.233.35:13410 [Mar 15 17:11:47] Found description format PCMU for ID 0 [Mar 15 17:11:47] Found description format telephone-event for ID 101 [Mar 15 17:11:47] Got unsupported a:fmtp in SDP offer [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/voipjet-006bf0a0 [Mar 15 17:11:47] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Mar 15 17:11:47] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 15 17:11:47] Peer audio RTP is at port 69.16.233.35:13410 [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 15 17:11:47] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;received=167.206.178.7;rport=5060 From: "6234928468" ;tag=as21926c7d To: ;tag=as7316cb62 Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 216 v=0 o=root 22129 22130 IN IP4 69.16.233.35 s=session c=IN IP4 69.16.233.35 t=0 0 m=audio 13410 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - <-------------> [Mar 15 17:11:47] -- Call on SIP/voipjet-006bf0a0 left from hold [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 15 17:11:47] -- Stopped music on hold on SIP/voipjet-00718ab0 [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4a8181e5;received=167.206.178.7;rport=5060 (92) [Mar 15 17:11:47] DEBUG[14890]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "6234928468" ;tag=as21926c7d (64) [Mar 15 17:11:47] -- SIP/voipjet-006bf0a0 is making progress passing it to SIP/voipjet-00718ab0 [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=as7316cb62 (49) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 (55) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Contact: (39) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Content-Length: 216 (19) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: (0) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: o=root 22129 22130 IN IP4 69.16.233.35 (38) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: c=IN IP4 69.16.233.35 (21) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: m=audio 13410 RTP/AVP 0 101 (27) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 15 17:11:47] --- (11 headers 10 lines) --- [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '52b9373d378a87ee5f281b192acea28f@167.206.178.7' of Request 102: Match Not Found [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:11641 handle_response_invite: SIP response 200 to standard invite [Mar 15 17:11:47] Found RTP audio format 0 [Mar 15 17:11:47] Found RTP audio format 101 [Mar 15 17:11:47] Peer audio RTP is at port 69.16.233.35:13410 [Mar 15 17:11:47] Found description format PCMU for ID 0 [Mar 15 17:11:47] Found description format telephone-event for ID 101 [Mar 15 17:11:47] Got unsupported a:fmtp in SDP offer [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/voipjet-006bf0a0 [Mar 15 17:11:47] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Mar 15 17:11:47] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 15 17:11:47] Peer audio RTP is at port 69.16.233.35:13410 [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:7980 build_route: build_route: Contact hop: [Mar 15 17:11:47] list_route: hop: [Mar 15 17:11:47] DEBUG[10175]: chan_sip.c:5643 reqprep: Strict routing enforced for session 52b9373d378a87ee5f281b192acea28f@167.206.178.7 [Mar 15 17:11:47] set_destination: Parsing for address/port to send to [Mar 15 17:11:47] set_destination: set destination to 69.16.233.35, port 5060 [Mar 15 17:11:47] Transmitting (no NAT) to 69.16.233.35:5060: ACK sip:16234928468@69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK4364ba3b;rport From: "6234928468" ;tag=as21926c7d To: ;tag=as7316cb62 Contact: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 15 17:11:47] -- Call on SIP/voipjet-006bf0a0 left from hold [Mar 15 17:11:47] DEBUG[14890]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/voipjet-006bf0a0 [Mar 15 17:11:47] -- SIP/voipjet-006bf0a0 answered SIP/voipjet-00718ab0 [Mar 15 17:11:47] DEBUG[10171]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - voipjet [Mar 15 17:11:47] DEBUG[10171]: chan_sip.c:15240 sip_devicestate: Checking device state for peer voipjet [Mar 15 17:11:47] DEBUG[10171]: devicestate.c:287 do_state_change: Changing state for SIP/voipjet - state 1 (Not in use) [Mar 15 17:11:47] DEBUG[14893]: app_queue.c:546 changethread: Device 'SIP/voipjet' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 15 17:11:47] DEBUG[14890]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to ulaw [Mar 15 17:11:47] DEBUG[14890]: rtp.c:2706 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Mar 15 17:11:48] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:48] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:49] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:69.45.170.230 SIP/2.0 (33) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK7ff38f90;rport (64) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as6f3533f6 (60) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (23) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Contact: (37) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 23ae57eb6d8c7b7f455e76784244df72@167.206.178.7 (55) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 15 Mar 2007 21:11:49 GMT (35) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Mar 15 17:11:49] Reliably Transmitting (no NAT) to 69.45.170.230:5060: OPTIONS sip:69.45.170.230 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK7ff38f90;rport From: "asterisk" ;tag=as6f3533f6 To: Contact: Call-ID: 23ae57eb6d8c7b7f455e76784244df72@167.206.178.7 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 15 Mar 2007 21:11:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38774 [Mar 15 17:11:49] <--- SIP read from 69.45.170.230:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK7ff38f90;rport From: "asterisk" ;tag=as6f3533f6 To: Call-ID: 23ae57eb6d8c7b7f455e76784244df72@167.206.178.7 CSeq: 102 OPTIONS Content-Length: 0 <-------------> [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 404 Not Found (21) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK7ff38f90;rport (64) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as6f3533f6 (60) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (23) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 23ae57eb6d8c7b7f455e76784244df72@167.206.178.7 (55) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: (0) [Mar 15 17:11:49] --- (7 headers 0 lines) --- [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38774 [Mar 15 17:11:49] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '23ae57eb6d8c7b7f455e76784244df72@167.206.178.7' of Request 102: Match Not Found [Mar 15 17:11:49] Really destroying SIP dialog '23ae57eb6d8c7b7f455e76784244df72@167.206.178.7' Method: OPTIONS [Mar 15 17:11:50] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:50] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:50] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:11:51] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:51] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:52] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:52] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:53] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:11:54] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:54] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:55] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:55] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:56] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:56] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:57] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:11:58] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:58] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:11:59] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:11:59] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:00] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:12:00] DEBUG[31834]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:12:00] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:00] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:01] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:12:02] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:02] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:02] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:12:03] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:03] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:04] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:04] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:05] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:12:06] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:06] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:07] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:07] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:08] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:08] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:09] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:12:10] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:10] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:11] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:11] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:12] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:12] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:12] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:12:14] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:14] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:15] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:12:15] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:15] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:16] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:16] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:17] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:12:18] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:18] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:19] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:12:19] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:19] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:19] DEBUG[14890]: channel.c:1586 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/voipjet-00718ab0' [Mar 15 17:12:20] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:20] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:22] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:22] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:23] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:23] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:66.63.165.151 SIP/2.0 (33) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK54b5f5c7;rport (64) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as64ed054f (60) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (23) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Contact: (37) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 08dfcf3754e28ec61125452e4eac6275@167.206.178.7 (55) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 15 Mar 2007 21:12:23 GMT (35) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Mar 15 17:12:23] Reliably Transmitting (no NAT) to 66.63.165.151:5060: OPTIONS sip:66.63.165.151 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK54b5f5c7;rport From: "asterisk" ;tag=as64ed054f To: Contact: Call-ID: 08dfcf3754e28ec61125452e4eac6275@167.206.178.7 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 15 Mar 2007 21:12:23 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 15 17:12:23] DEBUG[10175]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38777 [Mar 15 17:12:24] <--- SIP read from 66.63.165.151:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK54b5f5c7;rport=5060 From: "asterisk" ;tag=as64ed054f To: ;tag=0-tdb3221212128 Call-ID: 08dfcf3754e28ec61125452e4eac6275@167.206.178.7 CSeq: 102 OPTIONS Server: Sansay VSX 2.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE Content-Length: 0 <-------------> [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK54b5f5c7;rport=5060 (69) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as64ed054f (60) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=0-tdb3221212128 (43) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 08dfcf3754e28ec61125452e4eac6275@167.206.178.7 (55) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: Server: Sansay VSX 2.1 (22) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE (40) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Content-Length: 0 (17) [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 15 17:12:24] --- (9 headers 0 lines) --- [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38777 [Mar 15 17:12:24] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '08dfcf3754e28ec61125452e4eac6275@167.206.178.7' of Request 102: Match Not Found [Mar 15 17:12:24] Really destroying SIP dialog '08dfcf3754e28ec61125452e4eac6275@167.206.178.7' Method: OPTIONS [Mar 15 17:12:24] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:24] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:26] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:26] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:27] <--- SIP read from 69.16.233.35:5060 ---> BYE sip:6025161069@167.206.178.7 SIP/2.0 Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK7b964a3a;rport From: ;tag=as0de4c6d7 To: "6025161069" ;tag=as3f5c9eac Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: BYE sip:6025161069@167.206.178.7 SIP/2.0 (40) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK7b964a3a;rport (63) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: ;tag=as0de4c6d7 (51) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: "6025161069" ;tag=as3f5c9eac (62) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 (55) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 BYE (13) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Max-Forwards: 70 (16) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Content-Length: 0 (17) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 15 17:12:27] --- (9 headers 0 lines) --- [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:14629 handle_request: **** Received BYE (8) - Command in SIP BYE [Mar 15 17:12:27] Sending to 69.16.233.35 : 5060 (NAT) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:14190 handle_request_bye: Received bye, issuing owner hangup [Mar 15 17:12:27] <--- Transmitting (NAT) to 69.16.233.35:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK7b964a3a;received=69.16.233.35;rport=5060 From: ;tag=as0de4c6d7 To: "6025161069" ;tag=as3f5c9eac Call-ID: 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7 CSeq: 102 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 15 17:12:27] DEBUG[14890]: channel.c:3800 ast_generic_bridge: Didn't get a frame from channel: SIP/voipjet-00718ab0 [Mar 15 17:12:27] DEBUG[14890]: channel.c:4118 ast_channel_bridge: Bridge stops bridging channels SIP/voipjet-00718ab0 and SIP/voipjet-006bf0a0 [Mar 15 17:12:27] DEBUG[14890]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/voipjet-006bf0a0' [Mar 15 17:12:27] DEBUG[14890]: chan_sip.c:3312 sip_hangup: Hangup call SIP/voipjet-006bf0a0, SIP callid 52b9373d378a87ee5f281b192acea28f@167.206.178.7) [Mar 15 17:12:27] Scheduling destruction of SIP dialog '52b9373d378a87ee5f281b192acea28f@167.206.178.7' in 6400 ms (Method: INVITE) [Mar 15 17:12:27] DEBUG[14890]: chan_sip.c:5643 reqprep: Strict routing enforced for session 52b9373d378a87ee5f281b192acea28f@167.206.178.7 [Mar 15 17:12:27] set_destination: Parsing for address/port to send to [Mar 15 17:12:27] set_destination: set destination to 69.16.233.35, port 5060 [Mar 15 17:12:27] Reliably Transmitting (no NAT) to 69.16.233.35:5060: BYE sip:16234928468@69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK29e0c23c;rport From: "6234928468" ;tag=as21926c7d To: ;tag=as7316cb62 Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 15 17:12:27] DEBUG[14890]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38781 [Mar 15 17:12:27] DEBUG[14890]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/voipjet-006bf0a0 [Mar 15 17:12:27] DEBUG[14890]: rtp.c:1476 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 15 17:12:27] DEBUG[14890]: app_dial.c:1669 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 15 17:12:27] DEBUG[14890]: pbx.c:2389 __ast_pbx_run: Spawn extension (liveonly-transfer,s,7) exited non-zero on 'SIP/voipjet-00718ab0' [Mar 15 17:12:27] == Spawn extension (liveonly-transfer, s, 7) exited non-zero on 'SIP/voipjet-00718ab0' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:12:27] -- Executing [h@liveonly-transfer:1] Set("SIP/voipjet-00718ab0", "CDR(userfield)=press1transfer 20070315171145-1173993088.57.ulaw") in new stack [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:12:27] -- Executing [h@liveonly-transfer:2] Set("SIP/voipjet-00718ab0", "CDR(userfield2)=6173958126") in new stack [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:12:27] -- Executing [h@liveonly-transfer:3] Set("SIP/voipjet-00718ab0", "CDR(userfield3)=HUMAN-1200-1200") in new stack [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'Set' [Mar 15 17:12:27] -- Executing [h@liveonly-transfer:4] Set("SIP/voipjet-00718ab0", "CDR(accountcode)=484") in new stack [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1791 pbx_extension_helper: Launching 'NoOp' [Mar 15 17:12:27] -- Executing [h@liveonly-transfer:5] NoOp("SIP/voipjet-00718ab0", "6173958126") in new stack [Mar 15 17:12:27] DEBUG[10171]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - voipjet [Mar 15 17:12:27] DEBUG[10171]: chan_sip.c:15240 sip_devicestate: Checking device state for peer voipjet [Mar 15 17:12:27] DEBUG[10171]: devicestate.c:287 do_state_change: Changing state for SIP/voipjet - state 1 (Not in use) [Mar 15 17:12:27] DEBUG[14890]: channel.c:1385 spy_detach: Spy MixMonitor removed from channel SIP/voipjet-00718ab0 [Mar 15 17:12:27] == End MixMonitor Recording SIP/voipjet-00718ab0 [Mar 15 17:12:27] DEBUG[14890]: cdr_addon_mysql.c:222 mysql_log: cdr_mysql: inserting a CDR record. [Mar 15 17:12:27] DEBUG[14890]: cdr_addon_mysql.c:238 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield,userfield2,userfield3,userfield4,userfield5) VALUES ('2007-03-15 17:11:38','6025161069','6025161069','s','liveonly-transfer', 'SIP/voipjet-00718ab0','SIP/voipjet-006bf0a0','NoOp','6173958126',49,0,'ANSWERED',3,'484','press1transfer 20070315171145-1173993088.57.ulaw','6173958126','HUMAN-1200-1200','','2007-03-15 17:11:45') [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '6025161069' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '6025161069' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 's' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'liveonly-transfer' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/voipjet-00718ab0' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'SIP/voipjet-006bf0a0' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '6173958126' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-15 17:11:38' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '2007-03-15 17:12:27' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '49' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '0' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '484' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is '1173993088.57' [Mar 15 17:12:27] DEBUG[14890]: pbx.c:1644 pbx_substitute_variables_helper_full: Function result is 'press1transfer 20070315171145-1173993088.57.ulaw' [Mar 15 17:12:27] DEBUG[14890]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/voipjet-00718ab0' [Mar 15 17:12:27] DEBUG[14890]: chan_sip.c:3312 sip_hangup: Hangup call SIP/voipjet-00718ab0, SIP callid 05df7a19320d5ecf4e35ca5039941b88@167.206.178.7) [Mar 15 17:12:27] DEBUG[14890]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/voipjet-00718ab0 [Mar 15 17:12:27] DEBUG[10171]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - voipjet [Mar 15 17:12:27] DEBUG[10171]: chan_sip.c:15240 sip_devicestate: Checking device state for peer voipjet [Mar 15 17:12:27] DEBUG[10171]: devicestate.c:287 do_state_change: Changing state for SIP/voipjet - state 1 (Not in use) [Mar 15 17:12:27] DEBUG[14904]: app_queue.c:546 changethread: Device 'SIP/voipjet' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 15 17:12:27] DEBUG[14905]: app_queue.c:546 changethread: Device 'SIP/voipjet' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 15 17:12:27] <--- SIP read from 69.16.233.35:5060 ---> BYE sip:6234928468@167.206.178.7 SIP/2.0 Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK08705065;rport From: ;tag=as7316cb62 To: "6234928468" ;tag=as21926c7d Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Mar 15 17:12:27] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: BYE sip:6234928468@167.206.178.7 SIP/2.0 (40) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK08705065;rport (63) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: ;tag=as7316cb62 (51) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: "6234928468" ;tag=as21926c7d (62) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 (55) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 BYE (13) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Max-Forwards: 70 (16) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Content-Length: 0 (17) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 15 17:12:27] --- (9 headers 0 lines) --- [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:14629 handle_request: **** Received BYE (8) - Command in SIP BYE [Mar 15 17:12:27] Sending to 69.16.233.35 : 5060 (NAT) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 52b9373d378a87ee5f281b192acea28f@167.206.178.7 [Mar 15 17:12:27] Scheduling destruction of SIP dialog '52b9373d378a87ee5f281b192acea28f@167.206.178.7' in 6400 ms (Method: BYE) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:14194 handle_request_bye: Received bye, no owner, selfdestruct soon. [Mar 15 17:12:27] <--- Transmitting (NAT) to 69.16.233.35:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK08705065;received=69.16.233.35;rport=5060 From: ;tag=as7316cb62 To: "6234928468" ;tag=as21926c7d Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 15 17:12:27] Really destroying SIP dialog '05df7a19320d5ecf4e35ca5039941b88@167.206.178.7' Method: BYE [Mar 15 17:12:27] RTP-stats [Mar 15 17:12:27] * Our Receiver: [Mar 15 17:12:27] SSRC: 363945999 [Mar 15 17:12:27] Received packets: 2373 [Mar 15 17:12:27] Lost packets: 81 [Mar 15 17:12:27] Jitter: 0.0002 [Mar 15 17:12:27] Transit: -0.0004 [Mar 15 17:12:27] RR-count: 3 [Mar 15 17:12:27] * Our Sender: [Mar 15 17:12:27] SSRC: 209561222 [Mar 15 17:12:27] Sent packets: 1584 [Mar 15 17:12:27] Lost packets: 0 [Mar 15 17:12:27] Jitter: 0 [Mar 15 17:12:27] SR-count: 8 [Mar 15 17:12:27] RTT: 0.000000 [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:1866 retrans_pkt: SIP TIMER: Rescheduling retransmission #38781 (1) BYE - 8 [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:1880 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #38781)) [Mar 15 17:12:27] Retransmitting #1 (NAT) to 69.16.233.35:5060: BYE sip:16234928468@69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK29e0c23c;rport From: "6234928468" ;tag=as21926c7d To: ;tag=as7316cb62 Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 15 17:12:27] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK29e0c23c;received=167.206.178.7;rport=5060 From: "6234928468" ;tag=as21926c7d To: ;tag=as7316cb62 Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 <-------------> [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK29e0c23c;received=167.206.178.7;rport=5060 (92) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "6234928468" ;tag=as21926c7d (64) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=as7316cb62 (49) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 (55) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 103 BYE (13) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Contact: (39) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: (0) [Mar 15 17:12:27] --- (10 headers 0 lines) --- [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38781 [Mar 15 17:12:27] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '52b9373d378a87ee5f281b192acea28f@167.206.178.7' of Request 103: Match Not Found [Mar 15 17:12:27] Really destroying SIP dialog '52b9373d378a87ee5f281b192acea28f@167.206.178.7' Method: BYE [Mar 15 17:12:27] RTP-stats [Mar 15 17:12:27] * Our Receiver: [Mar 15 17:12:27] SSRC: 952808115 [Mar 15 17:12:27] Received packets: 1307 [Mar 15 17:12:27] Lost packets: 333 [Mar 15 17:12:27] Jitter: 0.0002 [Mar 15 17:12:27] Transit: 0.0000 [Mar 15 17:12:27] RR-count: 0 [Mar 15 17:12:27] * Our Sender: [Mar 15 17:12:27] SSRC: 617670641 [Mar 15 17:12:27] Sent packets: 1550 [Mar 15 17:12:27] Lost packets: 0 [Mar 15 17:12:27] Jitter: 0 [Mar 15 17:12:27] SR-count: 7 [Mar 15 17:12:27] RTT: 0.000000 [Mar 15 17:12:27] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:28] <--- SIP read from 69.16.233.35:5060 ---> BYE sip:6234928468@167.206.178.7 SIP/2.0 Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK08705065;rport From: ;tag=as7316cb62 To: "6234928468" ;tag=as21926c7d Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: BYE sip:6234928468@167.206.178.7 SIP/2.0 (40) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK08705065;rport (63) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: ;tag=as7316cb62 (51) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: "6234928468" ;tag=as21926c7d (62) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 (55) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 BYE (13) [Mar 15 17:12:28] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Max-Forwards: 70 (16) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Content-Length: 0 (17) [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 15 17:12:28] --- (9 headers 0 lines) --- [Mar 15 17:12:28] <--- Transmitting (no NAT) to 69.16.233.35:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 69.16.233.35:5060;branch=z9hG4bK08705065;received=69.16.233.35;rport=5060 From: ;tag=as7316cb62 To: "6234928468" ;tag=as21926c7d Call-ID: 52b9373d378a87ee5f281b192acea28f@167.206.178.7 CSeq: 102 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Mar 15 17:12:28] DEBUG[10175]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 361 [Mar 15 17:12:28] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:30] DEBUG[31834]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:12:30] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:12:30] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:30] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:31] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'SIPPEERS' [Mar 15 17:12:31] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:31] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:32] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:32] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:34] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:34] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:35] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:35] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:36] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:36] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:69.16.233.35 SIP/2.0 (32) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK455716ed;rport (64) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as1820c8b7 (60) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: (22) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Contact: (37) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 185fb15042e3d4e3393a8f4535bb3497@167.206.178.7 (55) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 15 Mar 2007 21:12:37 GMT (35) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Mar 15 17:12:37] Reliably Transmitting (no NAT) to 69.16.233.35:5060: OPTIONS sip:69.16.233.35 SIP/2.0 Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK455716ed;rport From: "asterisk" ;tag=as1820c8b7 To: Contact: Call-ID: 185fb15042e3d4e3393a8f4535bb3497@167.206.178.7 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 15 Mar 2007 21:12:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38783 [Mar 15 17:12:37] <--- SIP read from 69.16.233.35:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK455716ed;received=167.206.178.7;rport=5060 From: "asterisk" ;tag=as1820c8b7 To: ;tag=as318de7f0 Call-ID: 185fb15042e3d4e3393a8f4535bb3497@167.206.178.7 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Accept: application/sdp Content-Length: 0 <-------------> [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 404 Not Found (21) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 167.206.178.7:5060;branch=z9hG4bK455716ed;received=167.206.178.7;rport=5060 (92) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as1820c8b7 (60) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=as318de7f0 (37) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 185fb15042e3d4e3393a8f4535bb3497@167.206.178.7 (55) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 8: Accept: application/sdp (23) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:4573 parse_request: Header 10: (0) [Mar 15 17:12:37] --- (10 headers 0 lines) --- [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38783 [Mar 15 17:12:37] DEBUG[10175]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '185fb15042e3d4e3393a8f4535bb3497@167.206.178.7' of Request 102: Match Not Found [Mar 15 17:12:37] Really destroying SIP dialog '185fb15042e3d4e3393a8f4535bb3497@167.206.178.7' Method: OPTIONS [Mar 15 17:12:38] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:38] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:39] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:39] DEBUG[31148]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:40] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'DBPut' [Mar 15 17:12:40] DEBUG[14886]: manager.c:1984 process_message: Manager received command 'Command' [Mar 15 17:12:42] DEBUG[31080]: manager.c:1984 process_message: Manager received command 'DBPut' ASTEISK05*CLI>