[Feb 17 22:10:57] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> INVITE sip:800@sys0103.4voice.org SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-49481074db577545-1--d87543-;rport Max-Forwards: 70 Contact: To: "800" From: "test1";tag=a3022459 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 374 v=0 o=- 0 2 IN IP4 74.233.107.119 s=CounterPath X-Lite 3.0 c=IN IP4 74.233.107.119 t=0 0 m=audio 32428 RTP/AVP 107 119 100 106 0 105 98 8 101 a=fmtp:101 0-15 a=rtpmap:107 BV32/16000 a=rtpmap:119 BV32-FEC/16000 a=rtpmap:100 SPEEX/16000 a=rtpmap:106 SPEEX-FEC/16000 a=rtpmap:105 SPEEX-FEC/8000 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 0: INVITE sip:800@sys0103.4voice.org SIP/2.0 (41) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-49481074db577545-1--d87543-;rport (91) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 2: Max-Forwards: 70 (16) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 3: Contact: (38) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 4: To: "800" (37) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 5: From: "test1";tag=a3022459 (54) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 6: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 7: CSeq: 1 INVITE (14) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 8: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 9: Content-Type: application/sdp (29) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 10: User-Agent: X-Lite release 1011s stamp 41150 (44) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 11: Content-Length: 374 (19) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: v=0 (3) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: o=- 0 2 IN IP4 74.233.107.119 (29) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: s=CounterPath X-Lite 3.0 (24) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: c=IN IP4 74.233.107.119 (23) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: m=audio 32428 RTP/AVP 107 119 100 106 0 105 98 8 101 (52) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=fmtp:101 0-15 (15) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:107 BV32/16000 (23) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:119 BV32-FEC/16000 (27) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:100 SPEEX/16000 (24) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:106 SPEEX-FEC/16000 (28) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:105 SPEEX-FEC/8000 (27) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:98 iLBC/8000 (21) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:10:57] VERBOSE[13863] logger.c: --- (12 headers 15 lines) --- [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Setting NAT on RTP to Off [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Setting NAT on UDPTL to Off [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. - INVITE (With RTP) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 17 22:10:57] VERBOSE[13863] logger.c: Sending to 74.233.107.119 : 2678 (NAT) [Feb 17 22:10:57] VERBOSE[13863] logger.c: Using INVITE request as basis request - ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Setting NAT on RTP to On [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Setting NAT on UDPTL to On [Feb 17 22:10:57] VERBOSE[13863] logger.c: <--- Reliably Transmitting (NAT) to 74.233.107.119:2678 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-49481074db577545-1--d87543-;received=74.233.107.119;rport=2678 From: "test1";tag=a3022459 To: "800";tag=as356b4f30 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="50c385b5" Content-Length: 0 <------------> [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 407 Proxy Authentication Required (41) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-49481074db577545-1--d87543-;received=74.233.107.119;rport=2678 (120) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 2: From: "test1";tag=a3022459 (54) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 3: To: "800";tag=as356b4f30 (52) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 4: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 5: CSeq: 1 INVITE (14) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 9: Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="50c385b5" (76) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 11: (0) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Scheduling destruction of SIP dialog 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' in 32000 ms (Method: INVITE) [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found user '900' [Feb 17 22:10:57] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> ACK sip:800@sys0103.4voice.org SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-49481074db577545-1--d87543-;rport To: "800";tag=as356b4f30 From: "test1";tag=a3022459 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 1 ACK Content-Length: 0 <-------------> [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 0: ACK sip:800@sys0103.4voice.org SIP/2.0 (38) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-49481074db577545-1--d87543-;rport (91) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 2: To: "800";tag=as356b4f30 (52) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 3: From: "test1";tag=a3022459 (54) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 4: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 5: CSeq: 1 ACK (11) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 6: Content-Length: 0 (17) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 7: (0) [Feb 17 22:10:57] VERBOSE[13863] logger.c: --- (7 headers 0 lines) --- [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #122 [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Stopping retransmission on 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' of Response 1: Match Not Found [Feb 17 22:10:57] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> INVITE sip:800@sys0103.4voice.org SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;rport Max-Forwards: 70 Contact: To: "800" From: "test1";tag=a3022459 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Proxy-Authorization: Digest username="900",realm="asterisk",nonce="50c385b5",uri="sip:800@sys0103.4voice.org",response="d0c09401383a16145e878c4d86858acf",algorithm=MD5 User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 374 v=0 o=- 0 2 IN IP4 74.233.107.119 s=CounterPath X-Lite 3.0 c=IN IP4 74.233.107.119 t=0 0 m=audio 32428 RTP/AVP 107 119 100 106 0 105 98 8 101 a=fmtp:101 0-15 a=rtpmap:107 BV32/16000 a=rtpmap:119 BV32-FEC/16000 a=rtpmap:100 SPEEX/16000 a=rtpmap:106 SPEEX-FEC/16000 a=rtpmap:105 SPEEX-FEC/8000 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 0: INVITE sip:800@sys0103.4voice.org SIP/2.0 (41) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;rport (91) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 2: Max-Forwards: 70 (16) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 3: Contact: (38) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 4: To: "800" (37) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 5: From: "test1";tag=a3022459 (54) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 6: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 7: CSeq: 2 INVITE (14) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 8: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 9: Content-Type: application/sdp (29) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 10: Proxy-Authorization: Digest username="900",realm="asterisk",nonce="50c385b5",uri="sip:800@sys0103.4voice.org",response="d0c09401383a16145e878c4d86858acf",algorithm=MD5 (167) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 11: User-Agent: X-Lite release 1011s stamp 41150 (44) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 374 (19) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 13: (0) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: v=0 (3) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: o=- 0 2 IN IP4 74.233.107.119 (29) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: s=CounterPath X-Lite 3.0 (24) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: c=IN IP4 74.233.107.119 (23) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: m=audio 32428 RTP/AVP 107 119 100 106 0 105 98 8 101 (52) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=fmtp:101 0-15 (15) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:107 BV32/16000 (23) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:119 BV32-FEC/16000 (27) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:100 SPEEX/16000 (24) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:106 SPEEX-FEC/16000 (28) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:105 SPEEX-FEC/8000 (27) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:98 iLBC/8000 (21) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:10:57] VERBOSE[13863] logger.c: --- (13 headers 15 lines) --- [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 17 22:10:57] VERBOSE[13863] logger.c: Sending to 74.233.107.119 : 2678 (NAT) [Feb 17 22:10:57] VERBOSE[13863] logger.c: Using INVITE request as basis request - ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Setting NAT on RTP to On [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Setting NAT on UDPTL to On [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found user '900' [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 107 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 119 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 100 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 106 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 0 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 105 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 98 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 8 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found RTP audio format 101 [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Peer doesn't provide T.38 UDPTL [Feb 17 22:10:57] VERBOSE[13863] logger.c: Peer audio RTP is at port 74.233.107.119:32428 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Got unsupported a:fmtp in SDP offer [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found unknown media description format BV32 for ID 107 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found unknown media description format BV32-FEC for ID 119 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found audio description format SPEEX for ID 100 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found unknown media description format SPEEX-FEC for ID 106 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found unknown media description format SPEEX-FEC for ID 105 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found audio description format iLBC for ID 98 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Found audio description format telephone-event for ID 101 [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: T38 state changed to 0 on channel [Feb 17 22:10:57] VERBOSE[13863] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x60c (ulaw|alaw|speex|ilbc)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 17 22:10:57] VERBOSE[13863] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 17 22:10:57] VERBOSE[13863] logger.c: Peer audio RTP is at port 74.233.107.119:32428 [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Checking SIP call limits for device 900 [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Updating call counter for incoming call [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Call from peer '900' is 1 out of 50 [Feb 17 22:10:57] DEBUG[13863] devicestate.c: Notification of state change to be queued on device/channel SIP/900 [Feb 17 22:10:57] VERBOSE[13863] logger.c: Looking for 800 in from-internal (domain sys0103.4voice.org) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: This channel will not be able to handle video. [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: build_route: Contact hop: [Feb 17 22:10:57] VERBOSE[13863] logger.c: list_route: hop: [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: SIP/900-09b7d4f8: New call is still down.... Trying... [Feb 17 22:10:57] VERBOSE[13863] logger.c: <--- Transmitting (NAT) to 74.233.107.119:2678 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;received=74.233.107.119;rport=2678 From: "test1";tag=a3022459 To: "800" Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;received=74.233.107.119;rport=2678 (120) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 2: From: "test1";tag=a3022459 (54) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 3: To: "800" (37) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 4: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 5: CSeq: 2 INVITE (14) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 9: Contact: (32) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 17 22:10:57] DEBUG[13863] chan_sip.c: Header 11: (0) [Feb 17 22:10:57] DEBUG[13863] devicestate.c: Notification of state change to be queued on device/channel SIP/900-09b7d4f8 [Feb 17 22:10:57] DEBUG[13863] devicestate.c: Notification of state change to be queued on device/channel SIP/900 [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Macro' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [800@from-internal:1] Macro("SIP/900-09b7d4f8", "dialout-trunk|4|800||") in new stack [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/900-09b7d4f8", "DIAL_TRUNK=4") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:2] Set("SIP/900-09b7d4f8", "DIAL_NUMBER=800") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:3] Set("SIP/900-09b7d4f8", "ROUTE_PASSWD=") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:4] GotoIf("SIP/900-09b7d4f8", "1?noauth") in new stack [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Goto (macro-dialout-trunk,s,6) [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:6] GotoIf("SIP/900-09b7d4f8", "0?disabletrunk|1") in new stack [Feb 17 22:10:57] DEBUG[14107] pbx.c: Not taking any branch [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:7] Set("SIP/900-09b7d4f8", "_NODEST=") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:8] Set("SIP/900-09b7d4f8", "DIAL_TRUNK_OPTIONS=") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:9] Set("SIP/900-09b7d4f8", "GROUP()=OUT_4") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Macro' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:10] Macro("SIP/900-09b7d4f8", "user-callerid|SKIPTTL") in new stack [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is 'test' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'NoOp' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:1] NoOp("SIP/900-09b7d4f8", "user-callerid: test 900") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Noop [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:2] Set("SIP/900-09b7d4f8", "AMPUSER=900") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/900-09b7d4f8", "0?report") in new stack [Feb 17 22:10:57] DEBUG[14107] pbx.c: Not taking any branch [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:4] GotoIf("SIP/900-09b7d4f8", "0?start") in new stack [Feb 17 22:10:57] DEBUG[14107] pbx.c: Not taking any branch [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/900-09b7d4f8", "REALCALLERIDNUM=900") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'NoOp' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:6] NoOp("SIP/900-09b7d4f8", "REALCALLERIDNUM is 900") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: NoOp [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/900-09b7d4f8", "AMPUSER=900") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is 'Test' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/900-09b7d4f8", "AMPUSERCIDNAME=Test") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/900-09b7d4f8", "0?report") in new stack [Feb 17 22:10:57] DEBUG[14107] pbx.c: Not taking any branch [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '1' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:10] Set("SIP/900-09b7d4f8", "AMPUSERCID=900") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:11] Set("SIP/900-09b7d4f8", "CALLERID(all)="Test" <900>") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:12] Set("SIP/900-09b7d4f8", "REALCALLERIDNUM=900") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'NoOp' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:13] NoOp("SIP/900-09b7d4f8", "TTL: ARG1: SKIPTTL") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Noop [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:14] GotoIf("SIP/900-09b7d4f8", "1?continue") in new stack [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Goto (macro-user-callerid,s,23) [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '"Test" <900>' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'NoOp' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-user-callerid:23] NoOp("SIP/900-09b7d4f8", "Using CallerID "Test" <900>") in new stack [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: NoOp [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: Macro [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '900' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'Macro' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/900-09b7d4f8", "record-enable|900|OUT") in new stack [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '0' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/900-09b7d4f8", "0?2:4") in new stack [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Goto (macro-record-enable,s,4) [Feb 17 22:10:57] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:57] DEBUG[14107] pbx.c: Function result is '20080217-221057' [Feb 17 22:10:57] DEBUG[14107] pbx.c: Launching 'AGI' [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/900-09b7d4f8", "recordingcheck|20080217-221057|1203304257.6") in new stack [Feb 17 22:10:57] VERBOSE[14107] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck [Feb 17 22:10:57] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:10:57] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:10:57] DEBUG[13842] devicestate.c: Changing state for SIP/900 - state 2 (In use) [Feb 17 22:10:57] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:10:57] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:10:57] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900-09b7d4f8 [Feb 17 22:10:57] DEBUG[13842] chan_sip.c: Checking device state for peer 900-09b7d4f8 [Feb 17 22:10:57] DEBUG[13842] devicestate.c: Changing state for SIP/900-09b7d4f8 - state 4 (Invalid) [Feb 17 22:10:57] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:10:57] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:10:57] DEBUG[13842] devicestate.c: Changing state for SIP/900 - state 2 (In use) [Feb 17 22:10:57] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:10:57] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:10:58] DEBUG[13845] app_queue.c: Device 'SIP/900' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 17 22:10:58] DEBUG[13845] app_queue.c: Device 'SIP/900-09b7d4f8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 17 22:10:58] DEBUG[13845] app_queue.c: Device 'SIP/900' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 17 22:10:58] VERBOSE[14107] logger.c: recordingcheck|20080217-221057|1203304257.6: Outbound recording not enabled [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Auto destroying SIP dialog '699f85336b2b614a0e9bb2942034467a@64.135.85.195' [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Destroying SIP dialog 699f85336b2b614a0e9bb2942034467a@64.135.85.195 [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- AGI Script recordingcheck completed, returning 0 [Feb 17 22:10:58] VERBOSE[13863] logger.c: Really destroying SIP dialog '699f85336b2b614a0e9bb2942034467a@64.135.85.195' Method: OPTIONS [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '699f85336b2b614a0e9bb2942034467a@64.135.85.195' [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: 001. Rx OPTIONS / 102 OPTIONS / sip:5618071103@64.135.85.205 [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: 002. TxResp SIP/2.0 / 102 OPTIONS - 200 OK [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: 003. SchedDestroy 32000 ms [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: 004. AutoDestroy 699f85336b2b614a0e9bb2942034467a@64.135.85.195 [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '699f85336b2b614a0e9bb2942034467a@64.135.85.195' [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: AGI [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'NoOp' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-record-enable:5] NoOp("SIP/900-09b7d4f8", "No recording needed") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Noop [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Macro [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:12] GotoIf("SIP/900-09b7d4f8", "0?skipoutcid") in new stack [Feb 17 22:10:58] DEBUG[14107] pbx.c: Not taking any branch [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/900-09b7d4f8", "DIAL_TRUNK_OPTIONS=") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Macro' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:14] Macro("SIP/900-09b7d4f8", "outbound-callerid|4") in new stack [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:1] GotoIf("SIP/900-09b7d4f8", "1?start") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-outbound-callerid,s,3) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'NoOp' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:3] NoOp("SIP/900-09b7d4f8", "REALCALLERIDNUM is 900") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: NoOp [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:4] GotoIf("SIP/900-09b7d4f8", "1?normcid") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-outbound-callerid,s,9) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Function result is '' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:9] Set("SIP/900-09b7d4f8", "USEROUTCID=") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] db.c: Unable to find key '900/emergency_cid' in family 'DEVICE' [Feb 17 22:10:58] DEBUG[14107] func_db.c: DB: DEVICE/900/emergency_cid not found in database. [Feb 17 22:10:58] DEBUG[14107] pbx.c: Function result is '' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:10] Set("SIP/900-09b7d4f8", "EMERGENCYCID=") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:11] Set("SIP/900-09b7d4f8", "TRUNKOUTCID=") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:12] GotoIf("SIP/900-09b7d4f8", "1?trunkcid") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-outbound-callerid,s,16) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:16] GotoIf("SIP/900-09b7d4f8", "1?usercid") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-outbound-callerid,s,18) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:18] GotoIf("SIP/900-09b7d4f8", "1?report") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-outbound-callerid,s,22) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Function result is '"Test" <900>' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'NoOp' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-outbound-callerid:22] NoOp("SIP/900-09b7d4f8", "CallerID set to "Test" <900>") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: NoOp [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Macro [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:15] GotoIf("SIP/900-09b7d4f8", "1?nomax") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-dialout-trunk,s,17) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'AGI' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:17] AGI("SIP/900-09b7d4f8", "fixlocalprefix") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- AGI Script fixlocalprefix completed, returning 0 [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: AGI [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:18] Set("SIP/900-09b7d4f8", "OUTNUM=800") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Function result is 'AMP' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:19] Set("SIP/900-09b7d4f8", "custom=AMP") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:20] GotoIf("SIP/900-09b7d4f8", "1?gocall") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-dialout-trunk,s,22) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Macro' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:22] Macro("SIP/900-09b7d4f8", "dialout-trunk-predial-hook") in new stack [Feb 17 22:10:58] WARNING[14107] app_macro.c: Context 'macro-dialout-trunk-predial-hook' for macro 'dialout-trunk-predial-hook' lacks 's' extension, priority 1 [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Macro [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '0' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:23] GotoIf("SIP/900-09b7d4f8", "0?bypass|1") in new stack [Feb 17 22:10:58] DEBUG[14107] pbx.c: Not taking any branch [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/900-09b7d4f8", "1?customtrunk") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-dialout-trunk,s,27) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Function result is 'AMP:SIP/' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:27] Set("SIP/900-09b7d4f8", "pre_num=AMP:SIP/") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Function result is 'OUTNUM' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:28] Set("SIP/900-09b7d4f8", "the_num=OUTNUM") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Function result is '@sys0104.4voice.org' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:29] Set("SIP/900-09b7d4f8", "post_num=@sys0104.4voice.org") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:30] GotoIf("SIP/900-09b7d4f8", "1?outnum:skipoutnum") in new stack [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Goto (macro-dialout-trunk,s,31) [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Set' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:31] Set("SIP/900-09b7d4f8", "the_num=800") in new stack [Feb 17 22:10:58] DEBUG[14107] app_macro.c: Executed application: Set [Feb 17 22:10:58] DEBUG[14107] pbx.c: Launching 'Dial' [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Executing [s@macro-dialout-trunk:32] Dial("SIP/900-09b7d4f8", "SIP/800@sys0104.4voice.org|300|") in new stack [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: This channel will not be able to handle video. [Feb 17 22:10:58] DEBUG[14107] rtp.c: Seeded SDP of 'SIP/sys0104.4voice.org-09b77ad8' with that of 'SIP/900-09b7d4f8' [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable MACRO_DEPTH. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable the_num. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable post_num. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable pre_num. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable custom. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable OUTNUM. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable AGISTATUS. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable MACRO_PRIORITY. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable MACRO_CONTEXT. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable MACRO_EXTEN. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable ARG1. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable TRUNKOUTCID. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable EMERGENCYCID. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable USEROUTCID. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable DB_RESULT. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable DIAL_TRUNK_OPTIONS. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable ARG2. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable REALCALLERIDNUM. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable AMPUSERCID. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable AMPUSERCIDNAME. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable AMPUSER. [Feb 17 22:10:58] DEBUG[14107] channel.c: Copying soft-transferable variable NODEST. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable ROUTE_PASSWD. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable DIAL_NUMBER. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable DIAL_TRUNK. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable ARG4. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable ARG3. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable SIPCALLID. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable SIPUSERAGENT. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable SIPDOMAIN. [Feb 17 22:10:58] DEBUG[14107] channel.c: Not copying variable SIPURI. [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Outgoing Call for 800 [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Updating call counter for outgoing call [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Our T38 capability (3840), joint T38 capability (3840) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Feb 17 22:10:58] VERBOSE[14107] logger.c: Audio is at 64.135.85.205 port 19480 [Feb 17 22:10:58] VERBOSE[14107] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 17 22:10:58] VERBOSE[14107] logger.c: Adding codec 0x8 (alaw) to SDP [Feb 17 22:10:58] VERBOSE[14107] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: -- Done with adding codecs to SDP [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 0: INVITE sip:800@sys0104.4voice.org SIP/2.0 (41) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;rport (64) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 3: To: (32) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:10:58 GMT (35) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 13: Content-Length: 266 (19) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 14: (0) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: v=0 (3) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: o=root 13838 13838 IN IP4 64.135.85.205 (39) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: s=session (9) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: c=IN IP4 64.135.85.205 (22) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: m=audio 19480 RTP/AVP 0 8 101 (29) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:10:58] VERBOSE[14107] logger.c: Reliably Transmitting (no NAT) to 64.135.85.206:5060: INVITE sip:800@sys0104.4voice.org SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;rport From: "Test" ;tag=as395e0816 To: Contact: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 18 Feb 2008 03:10:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 266 v=0 o=root 13838 13838 IN IP4 64.135.85.205 s=session c=IN IP4 64.135.85.205 t=0 0 m=audio 19480 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 0: INVITE sip:800@sys0104.4voice.org SIP/2.0 (41) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;rport (64) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 3: To: (32) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:10:58 GMT (35) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 13: Content-Length: 266 (19) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 14: (0) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: v=0 (3) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: o=root 13838 13838 IN IP4 64.135.85.205 (39) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: s=session (9) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: c=IN IP4 64.135.85.205 (22) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: m=audio 19480 RTP/AVP 0 8 101 (29) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- Called 800@sys0104.4voice.org [Feb 17 22:10:58] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.206:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;received=64.135.85.205;rport=5060 From: "Test" ;tag=as395e0816 To: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <-------------> [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;received=64.135.85.205;rport=5060 (92) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 3: To: (32) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 9: Contact: (32) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 11: (0) [Feb 17 22:10:58] VERBOSE[13863] logger.c: --- (11 headers 0 lines) --- [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: *** SIP TIMER: Cancelling retransmission #124 - INVITE (got response) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' Request 102: Found [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: SIP response 100 to standard invite [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:900@74.233.107.119:2678;rinstance=2338bcb15ecbdad4 SIP/2.0 (70) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1a18da92;rport (64) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as300417f9 (58) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 3: To: (60) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 5f7fe4d4398457d82a2422d656abac45@64.135.85.205 (55) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:10:58 GMT (35) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:10:58] VERBOSE[13863] logger.c: Reliably Transmitting (NAT) to 74.233.107.119:2678: OPTIONS sip:900@74.233.107.119:2678;rinstance=2338bcb15ecbdad4 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1a18da92;rport From: "Unknown" ;tag=as300417f9 To: Contact: Call-ID: 5f7fe4d4398457d82a2422d656abac45@64.135.85.205 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 18 Feb 2008 03:10:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:900@74.233.107.119:2678;rinstance=2338bcb15ecbdad4 SIP/2.0 (70) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1a18da92;rport (64) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as300417f9 (58) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 3: To: (60) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 5f7fe4d4398457d82a2422d656abac45@64.135.85.205 (55) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:10:58 GMT (35) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 13: (0) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:10:58] VERBOSE[14110] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:10:58] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1a18da92;rport=5060 Contact: To: ;tag=fa6aca76 From: "Unknown";tag=as300417f9 Call-ID: 5f7fe4d4398457d82a2422d656abac45@64.135.85.205 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 0 <-------------> [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1a18da92;rport=5060 (69) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 2: Contact: (33) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=fa6aca76 (73) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 4: From: "Unknown";tag=as300417f9 (57) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 5f7fe4d4398457d82a2422d656abac45@64.135.85.205 (55) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 7: Accept: application/sdp (23) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 8: Accept-Language: en (19) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 10: User-Agent: X-Lite release 1011s stamp 41150 (44) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 11: Content-Length: 0 (17) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:10:58] VERBOSE[13863] logger.c: --- (12 headers 0 lines) --- [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #126 [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Stopping retransmission on '5f7fe4d4398457d82a2422d656abac45@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:10:58] VERBOSE[13863] logger.c: Really destroying SIP dialog '5f7fe4d4398457d82a2422d656abac45@64.135.85.205' Method: OPTIONS [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '5f7fe4d4398457d82a2422d656abac45@64.135.85.205' [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: 001. TxReqRel OPTIONS / 102 OPTIONS - -UNKNOWN- [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: 002. Rx SIP/2.0 / 102 OPTIONS / 200 OK [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '5f7fe4d4398457d82a2422d656abac45@64.135.85.205' [Feb 17 22:10:58] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.206:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;received=64.135.85.205;rport=5060 From: "Test" ;tag=as395e0816 To: ;tag=as17cb2782 Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <-------------> [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;received=64.135.85.205;rport=5060 (92) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=as17cb2782 (47) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 9: Contact: (32) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: Header 11: (0) [Feb 17 22:10:58] VERBOSE[13863] logger.c: --- (11 headers 0 lines) --- [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' Request 102: Found [Feb 17 22:10:58] DEBUG[13863] chan_sip.c: SIP response 180 to standard invite [Feb 17 22:10:58] DEBUG[13863] devicestate.c: Notification of state change to be queued on device/channel SIP/sys0104.4voice.org-09b77ad8 [Feb 17 22:10:58] DEBUG[13863] devicestate.c: Notification of state change to be queued on device/channel SIP/sys0104.4voice.org [Feb 17 22:10:58] VERBOSE[14107] logger.c: -- SIP/sys0104.4voice.org-09b77ad8 is ringing [Feb 17 22:10:58] DEBUG[14107] rtp.c: Setting early bridge SDP of 'SIP/900-09b7d4f8' with that of 'SIP/sys0104.4voice.org-09b77ad8' [Feb 17 22:10:58] VERBOSE[14107] logger.c: <--- Transmitting (NAT) to 74.233.107.119:2678 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;received=74.233.107.119;rport=2678 From: "test1";tag=a3022459 To: "800";tag=as55588b40 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;received=74.233.107.119;rport=2678 (120) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 2: From: "test1";tag=a3022459 (54) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 3: To: "800";tag=as55588b40 (52) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 4: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 5: CSeq: 2 INVITE (14) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 9: Contact: (32) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 17 22:10:58] DEBUG[14107] chan_sip.c: Header 11: (0) [Feb 17 22:10:58] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - sys0104.4voice.org-09b77ad8 [Feb 17 22:10:58] DEBUG[13842] chan_sip.c: Checking device state for peer sys0104.4voice.org-09b77ad8 [Feb 17 22:10:58] DEBUG[13842] devicestate.c: Changing state for SIP/sys0104.4voice.org-09b77ad8 - state 4 (Invalid) [Feb 17 22:10:58] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - sys0104.4voice.org [Feb 17 22:10:58] DEBUG[13842] chan_sip.c: Checking device state for peer sys0104.4voice.org [Feb 17 22:10:58] DEBUG[13845] app_queue.c: Device 'SIP/sys0104.4voice.org-09b77ad8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 17 22:10:58] DEBUG[13842] devicestate.c: Changing state for SIP/sys0104.4voice.org - state 6 (Ringing) [Feb 17 22:10:58] DEBUG[13845] app_queue.c: Device 'SIP/sys0104.4voice.org' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: Auto destroying SIP dialog '20cc13d111988f717cc0d5f530b58178@64.135.85.205' [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: Destroying SIP dialog 20cc13d111988f717cc0d5f530b58178@64.135.85.205 [Feb 17 22:10:59] VERBOSE[13863] logger.c: Really destroying SIP dialog '20cc13d111988f717cc0d5f530b58178@64.135.85.205' Method: REGISTER [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '20cc13d111988f717cc0d5f530b58178@64.135.85.205' [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 001. RegistryInit Account: jbloch@sip.telasip.net [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 002. AuthResp Auth response sent for jbloch in realm sip.telasip.net - nc 3 [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 003. TxReqRel REGISTER / 105 REGISTER - -UNKNOWN- [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 004. Rx SIP/2.0 / 105 REGISTER / 100 Trying [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 005. Rx SIP/2.0 / 105 REGISTER / 200 OK [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 006. SchedDestroy 32000 ms [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 007. AutoDestroy 20cc13d111988f717cc0d5f530b58178@64.135.85.205 [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '20cc13d111988f717cc0d5f530b58178@64.135.85.205' [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: Auto destroying SIP dialog '3e10254e055a8f5d432136897913dc7d@64.135.85.205' [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: Destroying SIP dialog 3e10254e055a8f5d432136897913dc7d@64.135.85.205 [Feb 17 22:10:59] VERBOSE[13863] logger.c: Really destroying SIP dialog '3e10254e055a8f5d432136897913dc7d@64.135.85.205' Method: REGISTER [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '3e10254e055a8f5d432136897913dc7d@64.135.85.205' [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 001. RegistryInit Account: 9100@sys0002.4voice.org [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 002. AuthResp Auth response sent for 9100 in realm asterisk - nc 2 [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 003. TxReqRel REGISTER / 106 REGISTER - -UNKNOWN- [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 004. Rx SIP/2.0 / 106 REGISTER / 100 Trying [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 005. Rx SIP/2.0 / 106 REGISTER / 401 Unauthorized [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 006. AuthResp Auth response sent for 9100 in realm asterisk - nc 1 [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 007. RegistryAuth Try: 1 [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 008. TxReqRel REGISTER / 107 REGISTER - -UNKNOWN- [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 009. Rx SIP/2.0 / 107 REGISTER / 100 Trying [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 010. Rx SIP/2.0 / 107 REGISTER / 200 OK [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 011. SchedDestroy 32000 ms [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: 012. AutoDestroy 3e10254e055a8f5d432136897913dc7d@64.135.85.205 [Feb 17 22:10:59] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '3e10254e055a8f5d432136897913dc7d@64.135.85.205' [Feb 17 22:11:02] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.206:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;received=64.135.85.205;rport=5060 From: "Test" ;tag=as395e0816 To: ;tag=as17cb2782 Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 11671 11671 IN IP4 64.135.85.206 s=session c=IN IP4 64.135.85.206 t=0 0 m=audio 10262 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6a9cd498;received=64.135.85.205;rport=5060 (92) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=as17cb2782 (47) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: Content-Length: 266 (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: o=root 11671 11671 IN IP4 64.135.85.206 (39) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: s=session (9) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: c=IN IP4 64.135.85.206 (22) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: m=audio 10262 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] VERBOSE[13863] logger.c: --- (12 headers 13 lines) --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Acked pending invite 102 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Stopping retransmission on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: SIP response 200 to standard invite [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found RTP audio format 0 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found RTP audio format 8 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found RTP audio format 101 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Peer doesn't provide T.38 UDPTL [Feb 17 22:11:02] VERBOSE[13863] logger.c: Peer audio RTP is at port 64.135.85.206:10262 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found audio description format PCMU for ID 0 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found audio description format PCMA for ID 8 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found audio description format telephone-event for ID 101 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Got unsupported a:fmtp in SDP offer [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: T38 state changed to 0 on channel SIP/sys0104.4voice.org-09b77ad8 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 17 22:11:02] VERBOSE[13863] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 17 22:11:02] VERBOSE[13863] logger.c: Peer audio RTP is at port 64.135.85.206:10262 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: We have an owner, now see if we need to change this call [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Updating call counter for outgoing call [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: build_route: Contact hop: [Feb 17 22:11:02] VERBOSE[13863] logger.c: list_route: hop: [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Strict routing enforced for session 5991b7291a24b2b806cdc46840d32352@64.135.85.205 [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: Parsing for address/port to send to [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: set destination to 64.135.85.206, port 5060 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Transmitting (no NAT) to 64.135.85.206:5060: ACK sip:800@64.135.85.206 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1dbacfff;rport From: "Test" ;tag=as395e0816 To: ;tag=as17cb2782 Contact: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: ACK sip:800@64.135.85.206 SIP/2.0 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1dbacfff;rport (64) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=as17cb2782 (47) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 ACK (13) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: (0) [Feb 17 22:11:02] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/sys0104.4voice.org-09b77ad8 [Feb 17 22:11:02] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/sys0104.4voice.org [Feb 17 22:11:02] VERBOSE[14107] logger.c: -- SIP/sys0104.4voice.org-09b77ad8 answered SIP/900-09b7d4f8 [Feb 17 22:11:02] DEBUG[14107] rtp.c: Setting early bridge SDP of 'SIP/900-09b7d4f8' with that of 'SIP/sys0104.4voice.org-09b77ad8' [Feb 17 22:11:02] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/900-09b7d4f8 [Feb 17 22:11:02] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/900 [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: SIP answering channel: SIP/900-09b7d4f8 [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Setting framing from config on incoming call [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Feb 17 22:11:02] VERBOSE[14107] logger.c: Audio is at 64.135.85.205 port 11514 [Feb 17 22:11:02] VERBOSE[14107] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 17 22:11:02] VERBOSE[14107] logger.c: Adding codec 0x8 (alaw) to SDP [Feb 17 22:11:02] VERBOSE[14107] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: -- Done with adding codecs to SDP [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 17 22:11:02] VERBOSE[14107] logger.c: <--- Reliably Transmitting (NAT) to 74.233.107.119:2678 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;received=74.233.107.119;rport=2678 From: "test1";tag=a3022459 To: "800";tag=as55588b40 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 266 v=0 o=root 13838 13838 IN IP4 64.135.85.205 s=session c=IN IP4 64.135.85.205 t=0 0 m=audio 11514 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-e87d0c6f8c2e1e71-1--d87543-;received=74.233.107.119;rport=2678 (120) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 2: From: "test1";tag=a3022459 (54) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 3: To: "800";tag=as55588b40 (52) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 4: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 5: CSeq: 2 INVITE (14) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 9: Contact: (32) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 10: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 11: Content-Length: 266 (19) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 12: (0) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: o=root 13838 13838 IN IP4 64.135.85.205 (39) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: s=session (9) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: c=IN IP4 64.135.85.205 (22) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: m=audio 11514 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:11:02] VERBOSE[14107] logger.c: -- Native bridging SIP/900-09b7d4f8 and SIP/sys0104.4voice.org-09b77ad8 [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Deferring reinvite on SIP 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' - It's audio will be redirected to IP 64.135.85.206 [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Sending reinvite on SIP '5991b7291a24b2b806cdc46840d32352@64.135.85.205' - It's audio soon redirected to IP 74.233.107.119 [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Strict routing enforced for session 5991b7291a24b2b806cdc46840d32352@64.135.85.205 [Feb 17 22:11:02] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.206:5060 ---> INVITE sip:900@64.135.85.205 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.206:5060;branch=z9hG4bK0989975b;rport From: ;tag=as17cb2782 To: "Test" ;tag=as395e0816 Contact: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 266 v=0 o=root 11671 11672 IN IP4 76.108.248.36 s=session c=IN IP4 76.108.248.36 t=0 0 m=audio 44712 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: INVITE sip:900@64.135.85.205 SIP/2.0 (36) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.206:5060;branch=z9hG4bK0989975b;rport (64) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: ;tag=as17cb2782 (49) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: "Test" ;tag=as395e0816 (49) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 13: Content-Length: 266 (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 14: (0) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: o=root 11671 11672 IN IP4 76.108.248.36 (39) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: s=session (9) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: c=IN IP4 76.108.248.36 (22) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: m=audio 44712 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] VERBOSE[13863] logger.c: --- (14 headers 13 lines) --- [Feb 17 22:11:02] VERBOSE[14107] logger.c: set_destination: Parsing for address/port to send to [Feb 17 22:11:02] VERBOSE[14107] logger.c: set_destination: set destination to 64.135.85.206, port 5060 [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Feb 17 22:11:02] VERBOSE[14107] logger.c: Audio is at 64.135.85.205 port 19480 [Feb 17 22:11:02] VERBOSE[14107] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 17 22:11:02] VERBOSE[14107] logger.c: Adding codec 0x8 (alaw) to SDP [Feb 17 22:11:02] VERBOSE[14107] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: -- Done with adding codecs to SDP [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Initializing already initialized SIP dialog 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (presumably reinvite) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 0: INVITE sip:800@64.135.85.206 SIP/2.0 (36) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK5867e251;rport (64) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 3: To: ;tag=as17cb2782 (47) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 6: CSeq: 103 INVITE (16) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 10: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 13: Content-Length: 268 (19) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 14: (0) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: o=root 13838 13839 IN IP4 74.233.107.119 (40) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: s=session (9) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: c=IN IP4 74.233.107.119 (23) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: m=audio 32428 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] VERBOSE[14107] logger.c: Reliably Transmitting (no NAT) to 64.135.85.206:5060: INVITE sip:800@64.135.85.206 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK5867e251;rport From: "Test" ;tag=as395e0816 To: ;tag=as17cb2782 Contact: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 268 v=0 o=root 13838 13839 IN IP4 74.233.107.119 s=session c=IN IP4 74.233.107.119 t=0 0 m=audio 32428 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 0: INVITE sip:800@64.135.85.206 SIP/2.0 (36) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK5867e251;rport (64) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 3: To: ;tag=as17cb2782 (47) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 6: CSeq: 103 INVITE (16) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 10: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 13: Content-Length: 268 (19) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Header 14: (0) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: o=root 13838 13839 IN IP4 74.233.107.119 (40) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: s=session (9) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: c=IN IP4 74.233.107.119 (23) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: m=audio 32428 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] DEBUG[14107] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Failed to grab owner channel lock, trying again. (SIP call 5991b7291a24b2b806cdc46840d32352@64.135.85.205) [Feb 17 22:11:02] DEBUG[14107] rtp.c: Ooh, format changed from unknown to ulaw [Feb 17 22:11:02] DEBUG[14107] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Feb 17 22:11:02] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - sys0104.4voice.org-09b77ad8 [Feb 17 22:11:02] DEBUG[13842] chan_sip.c: Checking device state for peer sys0104.4voice.org-09b77ad8 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Found SIP option: -replaces- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Matched SIP option: replaces [Feb 17 22:11:02] VERBOSE[13863] logger.c: <--- Transmitting (no NAT) to 64.135.85.206:5060 ---> SIP/2.0 491 Request Pending Via: SIP/2.0/UDP 64.135.85.206:5060;branch=z9hG4bK0989975b;received=64.135.85.206;rport=5060 From: ;tag=as17cb2782 To: "Test" ;tag=as395e0816 Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 <------------> [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 491 Request Pending (27) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.206:5060;branch=z9hG4bK0989975b;received=64.135.85.206;rport=5060 (92) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: ;tag=as17cb2782 (49) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: "Test" ;tag=as395e0816 (49) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: X-Asterisk-HangupCause: Normal Clearing (39) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: X-Asterisk-HangupCauseCode: 16 (30) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Got INVITE on call where we already have pending INVITE, deferring that - 5991b7291a24b2b806cdc46840d32352@64.135.85.205 [Feb 17 22:11:02] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.206:5060 ---> SIP/2.0 491 Request Pending Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK5867e251;received=64.135.85.205;rport=5060 From: "Test" ;tag=as395e0816 To: ;tag=as17cb2782 Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 103 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 <-------------> [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 491 Request Pending (27) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK5867e251;received=64.135.85.205;rport=5060 (92) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=as17cb2782 (47) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: CSeq: 103 INVITE (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: X-Asterisk-HangupCause: Normal Clearing (39) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: X-Asterisk-HangupCauseCode: 16 (30) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:11:02] VERBOSE[13863] logger.c: --- (12 headers 0 lines) --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Acked pending invite 103 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #130 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Stopping retransmission on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' of Request 103: Match Not Found [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: SIP response 491 to RE-invite on outgoing call 5991b7291a24b2b806cdc46840d32352@64.135.85.205 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Strict routing enforced for session 5991b7291a24b2b806cdc46840d32352@64.135.85.205 [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: Parsing for address/port to send to [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: set destination to 64.135.85.206, port 5060 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Transmitting (no NAT) to 64.135.85.206:5060: ACK sip:800@64.135.85.206 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK5867e251;rport From: "Test" ;tag=as395e0816 To: ;tag=as17cb2782 Contact: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: ACK sip:800@64.135.85.206 SIP/2.0 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK5867e251;rport (64) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: "Test" ;tag=as395e0816 (51) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=as17cb2782 (47) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 103 ACK (13) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: (0) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Reinvite race. Waiting 4 secs before retry [Feb 17 22:11:02] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.206:5060 ---> ACK sip:900@64.135.85.205 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.206:5060;branch=z9hG4bK0989975b;rport From: ;tag=as17cb2782 To: "Test" ;tag=as395e0816 Contact: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: ACK sip:900@64.135.85.205 SIP/2.0 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.206:5060;branch=z9hG4bK0989975b;rport (64) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: ;tag=as17cb2782 (49) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: "Test" ;tag=as395e0816 (49) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (55) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 ACK (13) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: (0) [Feb 17 22:11:02] VERBOSE[13863] logger.c: --- (10 headers 0 lines) --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 17 22:11:02] DEBUG[13842] devicestate.c: Changing state for SIP/sys0104.4voice.org-09b77ad8 - state 4 (Invalid) [Feb 17 22:11:02] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - sys0104.4voice.org [Feb 17 22:11:02] DEBUG[13842] chan_sip.c: Checking device state for peer sys0104.4voice.org [Feb 17 22:11:02] DEBUG[13845] app_queue.c: Device 'SIP/sys0104.4voice.org-09b77ad8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 17 22:11:02] DEBUG[13842] devicestate.c: Changing state for SIP/sys0104.4voice.org - state 2 (In use) [Feb 17 22:11:02] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900-09b7d4f8 [Feb 17 22:11:02] DEBUG[13842] chan_sip.c: Checking device state for peer 900-09b7d4f8 [Feb 17 22:11:02] DEBUG[13845] app_queue.c: Device 'SIP/sys0104.4voice.org' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 17 22:11:02] DEBUG[13842] devicestate.c: Changing state for SIP/900-09b7d4f8 - state 4 (Invalid) [Feb 17 22:11:02] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:11:02] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:11:02] DEBUG[13842] devicestate.c: Changing state for SIP/900 - state 2 (In use) [Feb 17 22:11:02] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:11:02] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:11:02] DEBUG[13845] app_queue.c: Device 'SIP/900-09b7d4f8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 17 22:11:02] DEBUG[13845] app_queue.c: Device 'SIP/900' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 17 22:11:02] DEBUG[14107] rtp.c: Got RTCP report of 132 bytes [Feb 17 22:11:02] DEBUG[14107] rtp.c: Forcing Marker bit, because SSRC has changed [Feb 17 22:11:02] DEBUG[14107] rtp.c: Ooh, format changed from unknown to ulaw [Feb 17 22:11:02] DEBUG[14107] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Feb 17 22:11:02] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> ACK sip:800@64.135.85.205 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-1c5b163f2c2b8b5b-1--d87543-;rport Max-Forwards: 70 Contact: To: "800";tag=as55588b40 From: "test1";tag=a3022459 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 2 ACK Proxy-Authorization: Digest username="900",realm="asterisk",nonce="50c385b5",uri="sip:800@sys0103.4voice.org",response="d0c09401383a16145e878c4d86858acf",algorithm=MD5 User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 0 <-------------> [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: ACK sip:800@64.135.85.205 SIP/2.0 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.1.100:2678;branch=z9hG4bK-d87543-1c5b163f2c2b8b5b-1--d87543-;rport (91) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: Contact: (38) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: To: "800";tag=as55588b40 (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: From: "test1";tag=a3022459 (54) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: CSeq: 2 ACK (11) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Proxy-Authorization: Digest username="900",realm="asterisk",nonce="50c385b5",uri="sip:800@sys0103.4voice.org",response="d0c09401383a16145e878c4d86858acf",algorithm=MD5 (167) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: User-Agent: X-Lite release 1011s stamp 41150 (44) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: (0) [Feb 17 22:11:02] VERBOSE[13863] logger.c: --- (11 headers 0 lines) --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #129 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Stopping retransmission on 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' of Response 2: Match Not Found [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Sending pending reinvite on 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Strict routing enforced for session ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: Parsing for address/port to send to [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: set destination to 74.233.107.119, port 2678 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Feb 17 22:11:02] VERBOSE[13863] logger.c: Audio is at 64.135.85.205 port 11514 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 17 22:11:02] VERBOSE[13863] logger.c: Adding codec 0x8 (alaw) to SDP [Feb 17 22:11:02] VERBOSE[13863] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: -- Done with adding codecs to SDP [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Initializing already initialized SIP dialog ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (presumably reinvite) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: INVITE sip:900@74.233.107.119:2678 SIP/2.0 (42) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK27200f4b;rport (64) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: "800";tag=as55588b40 (54) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: "test1";tag=a3022459 (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 13: Content-Length: 266 (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 14: (0) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: o=root 13838 13839 IN IP4 64.135.85.206 (39) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: s=session (9) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: c=IN IP4 64.135.85.206 (22) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: m=audio 10262 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] VERBOSE[13863] logger.c: Reliably Transmitting (NAT) to 74.233.107.119:2678: INVITE sip:900@74.233.107.119:2678 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK27200f4b;rport From: "800";tag=as55588b40 To: "test1";tag=a3022459 Contact: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 266 v=0 o=root 13838 13839 IN IP4 64.135.85.206 s=session c=IN IP4 64.135.85.206 t=0 0 m=audio 10262 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: INVITE sip:900@74.233.107.119:2678 SIP/2.0 (42) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK27200f4b;rport (64) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: "800";tag=as55588b40 (54) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: "test1";tag=a3022459 (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: Supported: replaces (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 13: Content-Length: 266 (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 14: (0) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: o=root 13838 13839 IN IP4 64.135.85.206 (39) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: s=session (9) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: c=IN IP4 64.135.85.206 (22) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: m=audio 10262 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=ptime:20 (10) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:11:02] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK27200f4b;rport=5060 Contact: To: "test1";tag=a3022459 From: "800";tag=as55588b40 Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 189 v=0 o=- 0 3 IN IP4 74.233.107.119 s=CounterPath X-Lite 3.0 c=IN IP4 74.233.107.119 t=0 0 m=audio 32428 RTP/AVP 0 8 101 a=fmtp:101 0-15 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK27200f4b;rport=5060 (69) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: Contact: (38) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: "test1";tag=a3022459 (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: From: "800";tag=as55588b40 (54) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Content-Type: application/sdp (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: User-Agent: X-Lite release 1011s stamp 41150 (44) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: Content-Length: 189 (19) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 11: (0) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: v=0 (3) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: o=- 0 3 IN IP4 74.233.107.119 (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: s=CounterPath X-Lite 3.0 (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: c=IN IP4 74.233.107.119 (23) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: t=0 0 (5) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: m=audio 32428 RTP/AVP 0 8 101 (29) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=fmtp:101 0-15 (15) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Line: a=sendrecv (10) [Feb 17 22:11:02] VERBOSE[13863] logger.c: --- (11 headers 9 lines) --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Acked pending invite 102 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #134 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Stopping retransmission on 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' of Request 102: Match Not Found [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: SIP response 200 to RE-invite on outgoing call ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found RTP audio format 0 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found RTP audio format 8 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found RTP audio format 101 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Peer doesn't provide T.38 UDPTL [Feb 17 22:11:02] VERBOSE[13863] logger.c: Peer audio RTP is at port 74.233.107.119:32428 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Got unsupported a:fmtp in SDP offer [Feb 17 22:11:02] VERBOSE[13863] logger.c: Found audio description format telephone-event for ID 101 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: T38 state changed to 0 on channel SIP/900-09b7d4f8 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 17 22:11:02] VERBOSE[13863] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 17 22:11:02] VERBOSE[13863] logger.c: Peer audio RTP is at port 74.233.107.119:32428 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: We have an owner, now see if we need to change this call [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Updating call counter for incoming call [Feb 17 22:11:02] DEBUG[13863] devicestate.c: Notification of state change to be queued on device/channel SIP/900 [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Strict routing enforced for session ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: Parsing for address/port to send to [Feb 17 22:11:02] VERBOSE[13863] logger.c: set_destination: set destination to 74.233.107.119, port 2678 [Feb 17 22:11:02] VERBOSE[13863] logger.c: Transmitting (NAT) to 74.233.107.119:2678: ACK sip:900@74.233.107.119:2678 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6fda6f98;rport From: "800";tag=as55588b40 To: "test1";tag=a3022459 Contact: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 0: ACK sip:900@74.233.107.119:2678 SIP/2.0 (39) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK6fda6f98;rport (64) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 2: From: "800";tag=as55588b40 (54) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 3: To: "test1";tag=a3022459 (52) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 4: Contact: (32) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 5: Call-ID: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. (53) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 ACK (13) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 17 22:11:02] DEBUG[13863] chan_sip.c: Header 10: (0) [Feb 17 22:11:02] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:11:02] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:11:02] DEBUG[13842] devicestate.c: Changing state for SIP/900 - state 2 (In use) [Feb 17 22:11:02] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:11:02] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:11:02] DEBUG[13845] app_queue.c: Device 'SIP/900' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 17 22:11:03] DEBUG[13869] manager.c: Manager received command 'Command' [Feb 17 22:11:03] DEBUG[13869] manager.c: Manager received command 'Command' [Feb 17 22:11:03] DEBUG[13869] manager.c: Manager received command 'Command' [Feb 17 22:11:03] VERBOSE[14114] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:05] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:07] DEBUG[14107] rtp.c: Got RTCP report of 64 bytes [Feb 17 22:11:08] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:08] VERBOSE[14118] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:11] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:12] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:13] VERBOSE[14122] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:14] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:17] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:17] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:18] VERBOSE[14125] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:20] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:22] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:23] VERBOSE[14129] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:23] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:25] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> <-------------> [Feb 17 22:11:25] DEBUG[13863] chan_sip.c: Header 0: (0) [Feb 17 22:11:25] DEBUG[13863] chan_sip.c: Line: (0) [Feb 17 22:11:25] VERBOSE[13863] logger.c: --- (0 headers 1 lines) --- [Feb 17 22:11:26] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.195:5060 ---> OPTIONS sip:5618071103@64.135.85.205 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.195:5060;branch=z9hG4bK200b5e1c;rport From: "Unknown" ;tag=as5c5e5ad8 To: Contact: Call-ID: 2c063d7901f375a621b18aa80e4f098e@64.135.85.195 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 18 Feb 2008 03:11:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 <-------------> [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:5618071103@64.135.85.205 SIP/2.0 (44) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.195:5060;branch=z9hG4bK200b5e1c;rport (64) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as5c5e5ad8 (58) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 3: To: (34) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 2c063d7901f375a621b18aa80e4f098e@64.135.85.195 (55) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:11:26 GMT (35) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 11: Content-Length: 0 (17) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:11:26] VERBOSE[13863] logger.c: --- (12 headers 0 lines) --- [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for 2c063d7901f375a621b18aa80e4f098e@64.135.85.195 - OPTIONS (No RTP) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 17 22:11:26] VERBOSE[13863] logger.c: Looking for 5618071103 in from-sip-external (domain 64.135.85.205) [Feb 17 22:11:26] VERBOSE[13863] logger.c: <--- Transmitting (no NAT) to 64.135.85.195:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.135.85.195:5060;branch=z9hG4bK200b5e1c;received=64.135.85.195;rport=5060 From: "Unknown" ;tag=as5c5e5ad8 To: ;tag=as5e50193e Call-ID: 2c063d7901f375a621b18aa80e4f098e@64.135.85.195 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.195:5060;branch=z9hG4bK200b5e1c;received=64.135.85.195;rport=5060 (92) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as5c5e5ad8 (58) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=as5e50193e (49) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 2c063d7901f375a621b18aa80e4f098e@64.135.85.195 (55) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 8: Supported: replaces (19) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 9: Contact: (28) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 10: Accept: application/sdp (23) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 11: Content-Length: 0 (17) [Feb 17 22:11:26] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:11:26] VERBOSE[13863] logger.c: Scheduling destruction of SIP dialog '2c063d7901f375a621b18aa80e4f098e@64.135.85.195' in 32000 ms (Method: OPTIONS) [Feb 17 22:11:26] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:27] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:28] VERBOSE[14132] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:30] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:32] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:33] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:33] VERBOSE[14136] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:36] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:37] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:38] VERBOSE[14139] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:39] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:42] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:42] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:43] VERBOSE[14143] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:45] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:47] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:48] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:48] VERBOSE[14146] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:51] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:52] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:53] VERBOSE[14150] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:54] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:55] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> <-------------> [Feb 17 22:11:55] DEBUG[13863] chan_sip.c: Header 0: (0) [Feb 17 22:11:55] DEBUG[13863] chan_sip.c: Line: (0) [Feb 17 22:11:55] VERBOSE[13863] logger.c: --- (0 headers 1 lines) --- [Feb 17 22:11:57] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:11:57] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:sys0002.4voice.org SIP/2.0 (38) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK3687a8a2;rport (64) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as3eaedbb3 (58) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 3: To: (28) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 226c8bd5135218ef623bd62b58f8df74@64.135.85.205 (55) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:11:57 GMT (35) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:11:57] VERBOSE[13863] logger.c: Reliably Transmitting (no NAT) to 64.135.85.195:5060: OPTIONS sip:sys0002.4voice.org SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK3687a8a2;rport From: "Unknown" ;tag=as3eaedbb3 To: Contact: Call-ID: 226c8bd5135218ef623bd62b58f8df74@64.135.85.205 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 18 Feb 2008 03:11:57 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:sys0002.4voice.org SIP/2.0 (38) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK3687a8a2;rport (64) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as3eaedbb3 (58) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 3: To: (28) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 226c8bd5135218ef623bd62b58f8df74@64.135.85.205 (55) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:11:57 GMT (35) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 13: (0) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:11:57] VERBOSE[13863] logger.c: <--- SIP read from 64.135.85.195:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK3687a8a2;received=64.135.85.205;rport=5060 From: "Unknown" ;tag=as3eaedbb3 To: ;tag=as524ac093 Call-ID: 226c8bd5135218ef623bd62b58f8df74@64.135.85.205 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Accept: application/sdp Content-Length: 0 <-------------> [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK3687a8a2;received=64.135.85.205;rport=5060 (92) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as3eaedbb3 (58) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=as524ac093 (43) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 226c8bd5135218ef623bd62b58f8df74@64.135.85.205 (55) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 8: Contact: (28) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 9: Accept: application/sdp (23) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 11: (0) [Feb 17 22:11:57] VERBOSE[13863] logger.c: --- (11 headers 0 lines) --- [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #136 [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Stopping retransmission on '226c8bd5135218ef623bd62b58f8df74@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:11:57] VERBOSE[13863] logger.c: Really destroying SIP dialog '226c8bd5135218ef623bd62b58f8df74@64.135.85.205' Method: OPTIONS [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '226c8bd5135218ef623bd62b58f8df74@64.135.85.205' [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: 001. TxReqRel OPTIONS / 102 OPTIONS - -UNKNOWN- [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: 002. Rx SIP/2.0 / 102 OPTIONS / 200 OK [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '226c8bd5135218ef623bd62b58f8df74@64.135.85.205' [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:sip.telasip.net SIP/2.0 (35) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK2e3a80e9;rport (64) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as50c220b1 (58) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 3: To: (25) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 04192efb34904fba1eb3b7db0b93adaa@64.135.85.205 (55) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:11:57 GMT (35) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:11:57] VERBOSE[13863] logger.c: Reliably Transmitting (no NAT) to 4.79.19.55:5060: OPTIONS sip:sip.telasip.net SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK2e3a80e9;rport From: "Unknown" ;tag=as50c220b1 To: Contact: Call-ID: 04192efb34904fba1eb3b7db0b93adaa@64.135.85.205 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 18 Feb 2008 03:11:57 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:sip.telasip.net SIP/2.0 (35) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK2e3a80e9;rport (64) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as50c220b1 (58) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 3: To: (25) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 04192efb34904fba1eb3b7db0b93adaa@64.135.85.205 (55) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:11:57 GMT (35) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 13: (0) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:11:57] VERBOSE[13863] logger.c: <--- SIP read from 4.79.19.55:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK2e3a80e9;rport=5060 From: "Unknown" ;tag=as50c220b1 To: ;tag=a75be19b503732e131ba8518af0fe952.8bdf Call-ID: 04192efb34904fba1eb3b7db0b93adaa@64.135.85.205 CSeq: 102 OPTIONS Accept: */* Accept-Encoding: Accept-Language: en Supported: Server: Telasip OS Proxy 1.2 Content-Length: 0 <-------------> [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK2e3a80e9;rport=5060 (69) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as50c220b1 (58) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=a75be19b503732e131ba8518af0fe952.8bdf (67) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 4: Call-ID: 04192efb34904fba1eb3b7db0b93adaa@64.135.85.205 (55) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 6: Accept: */* (11) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 7: Accept-Encoding: (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 8: Accept-Language: en (19) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 9: Supported: (11) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 10: Server: Telasip OS Proxy 1.2 (28) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 11: Content-Length: 0 (17) [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:11:57] VERBOSE[13863] logger.c: --- (12 headers 0 lines) --- [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #139 [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: Stopping retransmission on '04192efb34904fba1eb3b7db0b93adaa@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:11:57] VERBOSE[13863] logger.c: Really destroying SIP dialog '04192efb34904fba1eb3b7db0b93adaa@64.135.85.205' Method: OPTIONS [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '04192efb34904fba1eb3b7db0b93adaa@64.135.85.205' [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: 001. TxReqRel OPTIONS / 102 OPTIONS - -UNKNOWN- [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: 002. Rx SIP/2.0 / 102 OPTIONS / 200 OK [Feb 17 22:11:57] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '04192efb34904fba1eb3b7db0b93adaa@64.135.85.205' [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Auto destroying SIP dialog '2c063d7901f375a621b18aa80e4f098e@64.135.85.195' [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Destroying SIP dialog 2c063d7901f375a621b18aa80e4f098e@64.135.85.195 [Feb 17 22:11:58] VERBOSE[13863] logger.c: Really destroying SIP dialog '2c063d7901f375a621b18aa80e4f098e@64.135.85.195' Method: OPTIONS [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '2c063d7901f375a621b18aa80e4f098e@64.135.85.195' [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: 001. Rx OPTIONS / 102 OPTIONS / sip:5618071103@64.135.85.205 [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: 002. TxResp SIP/2.0 / 102 OPTIONS - 200 OK [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: 003. SchedDestroy 32000 ms [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: 004. AutoDestroy 2c063d7901f375a621b18aa80e4f098e@64.135.85.195 [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '2c063d7901f375a621b18aa80e4f098e@64.135.85.195' [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:900@74.233.107.119:2678;rinstance=2338bcb15ecbdad4 SIP/2.0 (70) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1e22322e;rport (64) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as17095769 (58) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 3: To: (60) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 53be2f097879736540bfe6b569f7c654@64.135.85.205 (55) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:11:58 GMT (35) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:11:58] VERBOSE[13863] logger.c: Reliably Transmitting (NAT) to 74.233.107.119:2678: OPTIONS sip:900@74.233.107.119:2678;rinstance=2338bcb15ecbdad4 SIP/2.0 Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1e22322e;rport From: "Unknown" ;tag=as17095769 To: Contact: Call-ID: 53be2f097879736540bfe6b569f7c654@64.135.85.205 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 18 Feb 2008 03:11:58 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 0: OPTIONS sip:900@74.233.107.119:2678;rinstance=2338bcb15ecbdad4 SIP/2.0 (70) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1e22322e;rport (64) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 2: From: "Unknown" ;tag=as17095769 (58) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 3: To: (60) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 4: Contact: (36) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 53be2f097879736540bfe6b569f7c654@64.135.85.205 (55) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 9: Date: Mon, 18 Feb 2008 03:11:58 GMT (35) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 11: Supported: replaces (19) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 12: Content-Length: 0 (17) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 13: (0) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #0 [Feb 17 22:11:58] VERBOSE[14153] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:11:58] VERBOSE[13863] logger.c: <--- SIP read from 74.233.107.119:2678 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1e22322e;rport=5060 Contact: To: ;tag=6711d23d From: "Unknown";tag=as17095769 Call-ID: 53be2f097879736540bfe6b569f7c654@64.135.85.205 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 0 <-------------> [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 1: Via: SIP/2.0/UDP 64.135.85.205:5060;branch=z9hG4bK1e22322e;rport=5060 (69) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 2: Contact: (33) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 3: To: ;tag=6711d23d (73) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 4: From: "Unknown";tag=as17095769 (57) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 5: Call-ID: 53be2f097879736540bfe6b569f7c654@64.135.85.205 (55) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 7: Accept: application/sdp (23) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 8: Accept-Language: en (19) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 10: User-Agent: X-Lite release 1011s stamp 41150 (44) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 11: Content-Length: 0 (17) [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Header 12: (0) [Feb 17 22:11:58] VERBOSE[13863] logger.c: --- (12 headers 0 lines) --- [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #142 [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: Stopping retransmission on '53be2f097879736540bfe6b569f7c654@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:11:58] VERBOSE[13863] logger.c: Really destroying SIP dialog '53be2f097879736540bfe6b569f7c654@64.135.85.205' Method: OPTIONS [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '53be2f097879736540bfe6b569f7c654@64.135.85.205' [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: 001. TxReqRel OPTIONS / 102 OPTIONS - -UNKNOWN- [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: 002. Rx SIP/2.0 / 102 OPTIONS / 200 OK [Feb 17 22:11:58] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '53be2f097879736540bfe6b569f7c654@64.135.85.205' [Feb 17 22:12:00] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:02] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:03] VERBOSE[14157] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:03] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:06] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:07] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:08] VERBOSE[14161] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:09] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:12] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:12] VERBOSE[13875] logger.c: -- Remote UNIX connection disconnected [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for 20cc13d111988f717cc0d5f530b58178@64.135.85.205 - REGISTER (No RTP) [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Scheduled a registration timeout for sip.telasip.net id #145 [Feb 17 22:12:12] VERBOSE[13863] logger.c: REGISTER attempt 1 to jbloch@sip.telasip.net [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for 3e10254e055a8f5d432136897913dc7d@64.135.85.205 - REGISTER (No RTP) [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Scheduled a registration timeout for sys0002.4voice.org id #147 [Feb 17 22:12:12] VERBOSE[13863] logger.c: REGISTER attempt 1 to 9100@sys0002.4voice.org [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3e10254e055a8f5d432136897913dc7d@64.135.85.205' Request 108: Found [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Stopping retransmission on '3e10254e055a8f5d432136897913dc7d@64.135.85.205' of Request 108: Match Not Found [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Initializing already initialized SIP dialog 3e10254e055a8f5d432136897913dc7d@64.135.85.205 (presumably reinvite) [Feb 17 22:12:12] VERBOSE[13863] logger.c: REGISTER attempt 2 to 9100@sys0002.4voice.org [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '3e10254e055a8f5d432136897913dc7d@64.135.85.205' Request 109: Found [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Stopping retransmission on '3e10254e055a8f5d432136897913dc7d@64.135.85.205' of Request 109: Match Not Found [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Registration successful [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Cancelling timeout 147 [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '20cc13d111988f717cc0d5f530b58178@64.135.85.205' Request 106: Found [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Stopping retransmission on '20cc13d111988f717cc0d5f530b58178@64.135.85.205' of Request 106: Match Not Found [Feb 17 22:12:12] DEBUG[13863] chan_sip.c: Initializing already initialized SIP dialog 20cc13d111988f717cc0d5f530b58178@64.135.85.205 (presumably reinvite) [Feb 17 22:12:12] VERBOSE[13863] logger.c: REGISTER attempt 2 to jbloch@sip.telasip.net [Feb 17 22:12:13] DEBUG[13863] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '20cc13d111988f717cc0d5f530b58178@64.135.85.205' Request 107: Found [Feb 17 22:12:13] DEBUG[13863] chan_sip.c: Stopping retransmission on '20cc13d111988f717cc0d5f530b58178@64.135.85.205' of Request 107: Match Not Found [Feb 17 22:12:13] DEBUG[13863] chan_sip.c: Registration successful [Feb 17 22:12:13] DEBUG[13863] chan_sip.c: Cancelling timeout 145 [Feb 17 22:12:13] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:13] VERBOSE[14165] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:16] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:17] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:18] VERBOSE[14171] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:19] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:20] DEBUG[13863] chan_sip.c: Invalid SIP message - rejected , no callid, len 553 [Feb 17 22:12:22] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:22] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:23] VERBOSE[14176] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:25] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:26] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for 452763d55609249224e9e27b42fc6c31@64.135.85.195 - OPTIONS (No RTP) [Feb 17 22:12:26] DEBUG[13863] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 17 22:12:27] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:28] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:28] VERBOSE[14179] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:31] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:32] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:33] VERBOSE[14183] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:34] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:37] DEBUG[14107] rtp.c: Got RTCP report of 44 bytes [Feb 17 22:12:37] DEBUG[14107] rtp.c: Got RTCP report of 176 bytes [Feb 17 22:12:38] VERBOSE[14186] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: Setting SIP_ALREADYGONE on dialog ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: Received bye, issuing owner hangup [Feb 17 22:12:39] DEBUG[14107] rtp.c: Oooh, got a hangup [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: Sending reinvite on SIP '5991b7291a24b2b806cdc46840d32352@64.135.85.205' - It's audio soon redirected to IP 64.135.85.205 [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: -- Done with adding codecs to SDP [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: Initializing already initialized SIP dialog 5991b7291a24b2b806cdc46840d32352@64.135.85.205 (presumably reinvite) [Feb 17 22:12:39] DEBUG[14107] channel.c: Returning from native bridge, channels: SIP/900-09b7d4f8, SIP/sys0104.4voice.org-09b77ad8 [Feb 17 22:12:39] DEBUG[14107] channel.c: Hanging up channel 'SIP/sys0104.4voice.org-09b77ad8' [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: Hangup call SIP/sys0104.4voice.org-09b77ad8, SIP callid 5991b7291a24b2b806cdc46840d32352@64.135.85.205) [Feb 17 22:12:39] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/sys0104.4voice.org-09b77ad8 [Feb 17 22:12:39] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/sys0104.4voice.org [Feb 17 22:12:39] DEBUG[14107] rtp.c: Channel '' has no RTP, not doing anything [Feb 17 22:12:39] DEBUG[14107] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Feb 17 22:12:39] DEBUG[14107] app_macro.c: Spawn extension (macro-dialout-trunk,s,32) exited non-zero on 'SIP/900-09b7d4f8' in macro 'dialout-trunk' [Feb 17 22:12:39] DEBUG[14107] pbx.c: Spawn extension (macro-dialout-trunk,s,32) exited non-zero on 'SIP/900-09b7d4f8' [Feb 17 22:12:39] VERBOSE[14107] logger.c: == Spawn extension (macro-dialout-trunk, s, 32) exited non-zero on 'SIP/900-09b7d4f8' [Feb 17 22:12:39] DEBUG[14107] channel.c: Soft-Hanging up channel 'SIP/900-09b7d4f8' [Feb 17 22:12:39] DEBUG[14107] pbx.c: Launching 'Macro' [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Executing [h@macro-dialout-trunk:1] Macro("SIP/900-09b7d4f8", "hangupcall") in new stack [Feb 17 22:12:39] DEBUG[14107] pbx.c: Launching 'ResetCDR' [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/900-09b7d4f8", "w") in new stack [Feb 17 22:12:39] DEBUG[14107] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. [Feb 17 22:12:39] DEBUG[14107] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2008-02-17 22:10:57','\"Test\" <900>','900','800','from-internal', 'SIP/900-09b7d4f8','SIP/sys0104.4voice.org-09b77ad8','Dial','SIP/800@sys0104.4voice.org|300|',102,97,'ANSWERED',3,'','1203304257.6') [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' Request 104: Found [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: SIP response 100 to standard invite [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: Acked pending invite 104 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: Stopping retransmission on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' of Request 104: Match Not Found [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: SIP response 200 to standard invite [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: T38 state changed to 0 on channel [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: Updating call counter for outgoing call [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: build_route: Retaining previous route: [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 17 22:12:39] NOTICE[13863] chan_sip.c: Unable to create/find SIP channel for this INVITE [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: Stopping retransmission on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' of Request 105: Match Not Found [Feb 17 22:12:39] DEBUG[14107] app_macro.c: Executed application: ResetCDR [Feb 17 22:12:39] DEBUG[14107] pbx.c: Launching 'NoCDR' [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Executing [s@macro-hangupcall:2] NoCDR("SIP/900-09b7d4f8", "") in new stack [Feb 17 22:12:39] DEBUG[14107] app_macro.c: Executed application: NoCDR [Feb 17 22:12:39] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:12:39] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Executing [s@macro-hangupcall:3] GotoIf("SIP/900-09b7d4f8", "1?skiprg") in new stack [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Goto (macro-hangupcall,s,6) [Feb 17 22:12:39] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:12:39] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:12:39] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Executing [s@macro-hangupcall:6] GotoIf("SIP/900-09b7d4f8", "1?skipblkvm") in new stack [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Goto (macro-hangupcall,s,9) [Feb 17 22:12:39] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:12:39] DEBUG[14107] pbx.c: Expression result is '1' [Feb 17 22:12:39] DEBUG[14107] pbx.c: Launching 'GotoIf' [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Executing [s@macro-hangupcall:9] GotoIf("SIP/900-09b7d4f8", "1?theend") in new stack [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Goto (macro-hangupcall,s,11) [Feb 17 22:12:39] DEBUG[14107] app_macro.c: Executed application: GotoIf [Feb 17 22:12:39] DEBUG[14107] pbx.c: Launching 'Hangup' [Feb 17 22:12:39] VERBOSE[14107] logger.c: -- Executing [s@macro-hangupcall:11] Hangup("SIP/900-09b7d4f8", "") in new stack [Feb 17 22:12:39] DEBUG[14107] app_macro.c: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'SIP/900-09b7d4f8' in macro 'hangupcall' [Feb 17 22:12:39] DEBUG[14107] pbx.c: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'SIP/900-09b7d4f8' [Feb 17 22:12:39] VERBOSE[14107] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/900-09b7d4f8' [Feb 17 22:12:39] DEBUG[14107] channel.c: Hanging up channel 'SIP/900-09b7d4f8' [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: Hangup call SIP/900-09b7d4f8, SIP callid ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.) [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: Updating call counter for incoming call [Feb 17 22:12:39] DEBUG[14107] chan_sip.c: Call from peer '900' removed from call limit 50 [Feb 17 22:12:39] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/900 [Feb 17 22:12:39] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/900-09b7d4f8 [Feb 17 22:12:39] DEBUG[14107] devicestate.c: Notification of state change to be queued on device/channel SIP/900 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: Stopping retransmission on '5991b7291a24b2b806cdc46840d32352@64.135.85.205' of Response 103: Match Not Found [Feb 17 22:12:39] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - sys0104.4voice.org-09b77ad8 [Feb 17 22:12:39] DEBUG[13842] chan_sip.c: Checking device state for peer sys0104.4voice.org-09b77ad8 [Feb 17 22:12:39] VERBOSE[13863] logger.c: Really destroying SIP dialog '5991b7291a24b2b806cdc46840d32352@64.135.85.205' Method: ACK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '5991b7291a24b2b806cdc46840d32352@64.135.85.205' [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 001. NewChan Channel SIP/sys0104.4voice.org-09b77ad8 - from 5991b7291a24b2b8 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 002. TxReqRel INVITE / 102 INVITE - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 003. Rx SIP/2.0 / 102 INVITE / 100 Trying [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 004. Rx SIP/2.0 / 102 INVITE / 180 Ringing [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 005. Rx SIP/2.0 / 102 INVITE / 200 OK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 006. TxReq ACK / 102 ACK - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 007. ReInv Re-invite sent [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 008. TxReqRel INVITE / 103 INVITE - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 009. Rx INVITE / 102 INVITE / sip:900@64.135.85.205 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 010. TxResp SIP/2.0 / 102 INVITE - 491 Request Pending [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 011. Rx SIP/2.0 / 103 INVITE / 491 Request Pending [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 012. TxReq ACK / 103 ACK - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 013. Rx ACK / 102 ACK / sip:900@64.135.85.205 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 014. ReInv Re-invite sent [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 015. TxReqRel INVITE / 104 INVITE - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 016. Hangup Cause Interworking, unspecified [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 017. SchedDestroy 32000 ms [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 018. CancelDestroy [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 019. Rx SIP/2.0 / 104 INVITE / 100 Trying [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 020. Rx SIP/2.0 / 104 INVITE / 200 OK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 021. TxReq ACK / 104 ACK - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 022. TxReqRel BYE / 105 BYE - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 023. SchedDestroy 32000 ms [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 024. Rx INVITE / 103 INVITE / sip:900@64.135.85.205 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 025. CancelDestroy [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 026. Invite New call: 5991b7291a24b2b806cdc46840d32352@64.135.85.205 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 027. TxRespRel SIP/2.0 / 103 INVITE - 503 Unavailable [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 028. SchedDestroy 32000 ms [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 029. Rx SIP/2.0 / 105 BYE / 200 OK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 030. Rx ACK / 103 ACK / sip:900@64.135.85.205 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '5991b7291a24b2b806cdc46840d32352@64.135.85.205' [Feb 17 22:12:39] VERBOSE[13863] logger.c: Really destroying SIP dialog 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' Method: BYE [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 001. Rx INVITE / 1 INVITE / sip:800@sys0103.4voice.org [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 002. AuthChal Auth challenge sent for - nc 0 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 003. TxRespRel SIP/2.0 / 1 INVITE - 407 Proxy Authentication Required [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 004. SchedDestroy 32000 ms [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 005. Rx ACK / 1 ACK / sip:800@sys0103.4voice.org [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 006. Rx INVITE / 2 INVITE / sip:800@sys0103.4voice.org [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 007. CancelDestroy [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 008. Invite New call: ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ. [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 009. AuthOK Auth challenge succesful for 900 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 010. NewChan Channel SIP/900-09b7d4f8 - from ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDF [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 011. TxResp SIP/2.0 / 2 INVITE - 100 Trying [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 012. TxResp SIP/2.0 / 2 INVITE - 180 Ringing [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 013. TxRespRel SIP/2.0 / 2 INVITE - 200 OK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 014. Rx ACK / 2 ACK / sip:800@64.135.85.205 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 015. ReInv Re-invite sent [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 016. TxReqRel INVITE / 102 INVITE - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 017. Rx SIP/2.0 / 102 INVITE / 200 OK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 018. TxReq ACK / 102 ACK - -UNKNOWN- [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 019. Rx BYE / 3 BYE / sip:800@64.135.85.205 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 020. RTCPaudio Quality:ssrc=32204973;themssrc=2708751216;lp=0;rxjitter=0.00300 [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 021. TxResp SIP/2.0 / 3 BYE - 200 OK [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: 022. Hangup Cause Normal Clearing [Feb 17 22:12:39] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for 'ZDcwZTkxZTNlYzM1ZDY4YjU3YzQyMDFjYWM4ZjFkZjQ.' [Feb 17 22:12:39] DEBUG[13842] devicestate.c: Changing state for SIP/sys0104.4voice.org-09b77ad8 - state 4 (Invalid) [Feb 17 22:12:39] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - sys0104.4voice.org [Feb 17 22:12:39] DEBUG[13842] chan_sip.c: Checking device state for peer sys0104.4voice.org [Feb 17 22:12:39] DEBUG[13845] app_queue.c: Device 'SIP/sys0104.4voice.org-09b77ad8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 17 22:12:39] DEBUG[13842] devicestate.c: Changing state for SIP/sys0104.4voice.org - state 1 (Not in use) [Feb 17 22:12:39] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:12:39] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:12:39] DEBUG[13842] devicestate.c: Changing state for SIP/900 - state 1 (Not in use) [Feb 17 22:12:39] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:12:39] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:12:39] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900-09b7d4f8 [Feb 17 22:12:39] DEBUG[13842] chan_sip.c: Checking device state for peer 900-09b7d4f8 [Feb 17 22:12:39] DEBUG[13845] app_queue.c: Device 'SIP/sys0104.4voice.org' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 17 22:12:39] DEBUG[13845] app_queue.c: Device 'SIP/900' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 17 22:12:39] DEBUG[13842] devicestate.c: Changing state for SIP/900-09b7d4f8 - state 4 (Invalid) [Feb 17 22:12:39] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:12:39] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:12:39] DEBUG[13842] devicestate.c: Changing state for SIP/900 - state 1 (Not in use) [Feb 17 22:12:39] DEBUG[13842] devicestate.c: No provider found, checking channel drivers for SIP - 900 [Feb 17 22:12:39] DEBUG[13842] chan_sip.c: Checking device state for peer 900 [Feb 17 22:12:39] DEBUG[13845] app_queue.c: Device 'SIP/900-09b7d4f8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 17 22:12:39] DEBUG[13845] app_queue.c: Device 'SIP/900' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 17 22:12:43] VERBOSE[14190] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: Auto destroying SIP dialog '3e10254e055a8f5d432136897913dc7d@64.135.85.205' [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: Destroying SIP dialog 3e10254e055a8f5d432136897913dc7d@64.135.85.205 [Feb 17 22:12:44] VERBOSE[13863] logger.c: Really destroying SIP dialog '3e10254e055a8f5d432136897913dc7d@64.135.85.205' Method: REGISTER [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '3e10254e055a8f5d432136897913dc7d@64.135.85.205' [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 001. RegistryInit Account: 9100@sys0002.4voice.org [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 002. AuthResp Auth response sent for 9100 in realm asterisk - nc 2 [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 003. TxReqRel REGISTER / 108 REGISTER - -UNKNOWN- [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 004. Rx SIP/2.0 / 108 REGISTER / 100 Trying [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 005. Rx SIP/2.0 / 108 REGISTER / 401 Unauthorized [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 006. AuthResp Auth response sent for 9100 in realm asterisk - nc 1 [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 007. RegistryAuth Try: 1 [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 008. TxReqRel REGISTER / 109 REGISTER - -UNKNOWN- [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 009. Rx SIP/2.0 / 109 REGISTER / 100 Trying [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 010. Rx SIP/2.0 / 109 REGISTER / 200 OK [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 011. SchedDestroy 32000 ms [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: 012. AutoDestroy 3e10254e055a8f5d432136897913dc7d@64.135.85.205 [Feb 17 22:12:44] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '3e10254e055a8f5d432136897913dc7d@64.135.85.205' [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: Auto destroying SIP dialog '20cc13d111988f717cc0d5f530b58178@64.135.85.205' [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: Destroying SIP dialog 20cc13d111988f717cc0d5f530b58178@64.135.85.205 [Feb 17 22:12:45] VERBOSE[13863] logger.c: Really destroying SIP dialog '20cc13d111988f717cc0d5f530b58178@64.135.85.205' Method: REGISTER [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '20cc13d111988f717cc0d5f530b58178@64.135.85.205' [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 001. RegistryInit Account: jbloch@sip.telasip.net [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 002. AuthResp Auth response sent for jbloch in realm sip.telasip.net - nc 4 [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 003. TxReqRel REGISTER / 106 REGISTER - -UNKNOWN- [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 004. Rx SIP/2.0 / 106 REGISTER / 100 Trying [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 005. Rx SIP/2.0 / 106 REGISTER / 401 Unauthorized [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 006. AuthResp Auth response sent for jbloch in realm sip.telasip.net - nc 1 [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 007. RegistryAuth Try: 1 [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 008. TxReqRel REGISTER / 107 REGISTER - -UNKNOWN- [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 009. Rx SIP/2.0 / 107 REGISTER / 100 Trying [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 010. Rx SIP/2.0 / 107 REGISTER / 200 OK [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 011. SchedDestroy 32000 ms [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: 012. AutoDestroy 20cc13d111988f717cc0d5f530b58178@64.135.85.205 [Feb 17 22:12:45] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '20cc13d111988f717cc0d5f530b58178@64.135.85.205' [Feb 17 22:12:48] VERBOSE[14193] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:53] VERBOSE[14197] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: Stopping retransmission on '3b5164333d8f801410a5968e0a917d66@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:12:57] VERBOSE[13863] logger.c: Really destroying SIP dialog '3b5164333d8f801410a5968e0a917d66@64.135.85.205' Method: OPTIONS [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '3b5164333d8f801410a5968e0a917d66@64.135.85.205' [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: 001. TxReqRel OPTIONS / 102 OPTIONS - -UNKNOWN- [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: 002. Rx SIP/2.0 / 102 OPTIONS / 200 OK [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '3b5164333d8f801410a5968e0a917d66@64.135.85.205' [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: Stopping retransmission on '353434ee48d1c8007853baab1825fe77@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:12:57] VERBOSE[13863] logger.c: Really destroying SIP dialog '353434ee48d1c8007853baab1825fe77@64.135.85.205' Method: OPTIONS [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '353434ee48d1c8007853baab1825fe77@64.135.85.205' [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: 001. TxReqRel OPTIONS / 102 OPTIONS - -UNKNOWN- [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: 002. Rx SIP/2.0 / 102 OPTIONS / 200 OK [Feb 17 22:12:57] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '353434ee48d1c8007853baab1825fe77@64.135.85.205' [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: Auto destroying SIP dialog '452763d55609249224e9e27b42fc6c31@64.135.85.195' [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: Destroying SIP dialog 452763d55609249224e9e27b42fc6c31@64.135.85.195 [Feb 17 22:12:58] VERBOSE[13863] logger.c: Really destroying SIP dialog '452763d55609249224e9e27b42fc6c31@64.135.85.195' Method: OPTIONS [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '452763d55609249224e9e27b42fc6c31@64.135.85.195' [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: 001. Rx OPTIONS / 102 OPTIONS / sip:5618071103@64.135.85.205 [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: 002. TxResp SIP/2.0 / 102 OPTIONS - 200 OK [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: 003. SchedDestroy 32000 ms [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: 004. AutoDestroy 452763d55609249224e9e27b42fc6c31@64.135.85.195 [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '452763d55609249224e9e27b42fc6c31@64.135.85.195' [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Feb 17 22:12:58] VERBOSE[14200] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: Stopping retransmission on '414d8bda7de48ead2824d4745cdefab5@64.135.85.205' of Request 102: Match Not Found [Feb 17 22:12:58] VERBOSE[13863] logger.c: Really destroying SIP dialog '414d8bda7de48ead2824d4745cdefab5@64.135.85.205' Method: OPTIONS [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: ---------- SIP HISTORY for '414d8bda7de48ead2824d4745cdefab5@64.135.85.205' [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: * SIP Call [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: 001. TxReqRel OPTIONS / 102 OPTIONS - -UNKNOWN- [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: 002. Rx SIP/2.0 / 102 OPTIONS / 200 OK [Feb 17 22:12:58] DEBUG[13863] chan_sip.c: ---------- END SIP HISTORY for '414d8bda7de48ead2824d4745cdefab5@64.135.85.205' [Feb 17 22:13:03] DEBUG[13869] manager.c: Manager received command 'Command' [Feb 17 22:13:03] DEBUG[13869] manager.c: Manager received command 'Command' [Feb 17 22:13:03] DEBUG[13869] manager.c: Manager received command 'Command' [Feb 17 22:13:03] VERBOSE[14204] logger.c: == Connect attempt from '127.0.0.1' unable to authenticate