[Apr 7 16:45:42] Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'sdnatl-pbx01.sdnglobal.com' (pid 25338)*CLI> *CLI> *CLI> *CLI> core set debug 4 Core debug was 5 and is now 4 *CLI> core set verbose 4 Verbosity was 5 and is now 4 *CLI> sip set debug SIP Debugging enabled *CLI> [Apr 7 16:46:40] DEBUG[25356]: chan_iax2.c:7112 socket_process: Peer pbx01: got pong, lastms 7, historicms 7, maxms 5000 [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: OPTIONS sip:7111@172.30.45.130 SIP/2.0 (38) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK1b090600;rport (62) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as74294d92 (58) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: (28) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: Contact: (35) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 77b1a966680935ce45c5be5b089c31f4@172.30.32.5 (53) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: User-Agent: SDN Global PBX (26) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Date: Sat, 07 Apr 2007 16:46:41 GMT (35) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: Supported: replaces (19) [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 12: Content-Length: 0 (17) [Apr 7 16:46:41] Reliably Transmitting (NAT) to 172.30.45.130:5060: OPTIONS sip:7111@172.30.45.130 SIP/2.0 Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK1b090600;rport From: "asterisk" ;tag=as74294d92 To: Contact: Call-ID: 77b1a966680935ce45c5be5b089c31f4@172.30.32.5 CSeq: 102 OPTIONS User-Agent: SDN Global PBX Max-Forwards: 70 Date: Sat, 07 Apr 2007 16:46:41 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 7 16:46:41] DEBUG[25349]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #8 [Apr 7 16:46:42] <--- SIP read from 172.30.45.130:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK1b090600;rport From: "asterisk" ;tag=as74294d92 To: ;tag=C6905CEB-8E04615C CSeq: 102 OPTIONS Call-ID: 77b1a966680935ce45c5be5b089c31f4@172.30.32.5 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Content-Length: 0 <-------------> [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK1b090600;rport (62) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as74294d92 (58) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=C6905CEB-8E04615C (50) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 102 OPTIONS (17) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 77b1a966680935ce45c5be5b089c31f4@172.30.32.5 (53) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Content-Length: 0 (17) [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: (0) [Apr 7 16:46:42] --- (10 headers 0 lines) --- [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #8 [Apr 7 16:46:42] DEBUG[25349]: chan_sip.c:2091 __sip_ack: Stopping retransmission on '77b1a966680935ce45c5be5b089c31f4@172.30.32.5' of Request 102: Match Not Found [Apr 7 16:46:42] Really destroying SIP dialog '77b1a966680935ce45c5be5b089c31f4@172.30.32.5' Method: OPTIONS [Apr 7 16:46:43] <--- SIP read from 172.30.45.130:5060 ---> INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bKafd8e13e258EF45 From: "7111" ;tag=DAD37944-650A6EE9 To: CSeq: 1 INVITE Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1175902012 1175902012 IN IP4 172.30.45.130 s=Polycom IP Phone c=IN IP4 172.30.45.130 t=0 0 m=audio 2230 RTP/AVP 0 18 8 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 (46) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bKafd8e13e258EF45 (60) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "7111" ;tag=DAD37944-650A6EE9 (57) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: (37) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 1 INVITE (14) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 (49) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: Max-Forwards: 70 (16) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 13: Content-Length: 251 (19) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 14: (0) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: o=- 1175902012 1175902012 IN IP4 172.30.45.130 (46) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: c=IN IP4 172.30.45.130 (22) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: m=audio 2230 RTP/AVP 0 18 8 101 (31) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 7 16:46:43] --- (14 headers 11 lines) --- [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to On [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2582 do_setnat: Setting NAT on VRTP to On [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2587 do_setnat: Setting NAT on UDPTL to On [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 116ef430-dd07d2b2-a681586f@172.30.45.130 - INVITE (With RTP) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:1682 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:1690 parse_sip_options: Found SIP option: -100rel- [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:1696 parse_sip_options: Matched SIP option: 100rel [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:1690 parse_sip_options: Found SIP option: -replaces- [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:1696 parse_sip_options: Matched SIP option: replaces [Apr 7 16:46:43] Sending to 172.30.45.130 : 5060 (NAT) [Apr 7 16:46:43] Using INVITE request as basis request - 116ef430-dd07d2b2-a681586f@172.30.45.130 [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to On [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2582 do_setnat: Setting NAT on VRTP to On [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2587 do_setnat: Setting NAT on UDPTL to On [Apr 7 16:46:43] <--- Reliably Transmitting (NAT) to 172.30.45.130:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bKafd8e13e258EF45;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as29d82416 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 1 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="19751752" Content-Length: 0 <------------> [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #11 [Apr 7 16:46:43] Scheduling destruction of SIP dialog '116ef430-dd07d2b2-a681586f@172.30.45.130' in 32000 ms (Method: INVITE) [Apr 7 16:46:43] Found user '7111' [Apr 7 16:46:43] <--- SIP read from 172.30.45.130:5060 ---> INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bKafd8e13e258EF45 From: "7111" ;tag=DAD37944-650A6EE9 To: CSeq: 1 INVITE Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1175902012 1175902012 IN IP4 172.30.45.130 s=Polycom IP Phone c=IN IP4 172.30.45.130 t=0 0 m=audio 2230 RTP/AVP 0 18 8 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 (46) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bKafd8e13e258EF45 (60) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "7111" ;tag=DAD37944-650A6EE9 (57) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: (37) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 1 INVITE (14) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 (49) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: Max-Forwards: 70 (16) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 13: Content-Length: 251 (19) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 14: (0) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: o=- 1175902012 1175902012 IN IP4 172.30.45.130 (46) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: c=IN IP4 172.30.45.130 (22) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: m=audio 2230 RTP/AVP 0 18 8 101 (31) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 7 16:46:43] --- (14 headers 11 lines) --- [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:14715 handle_request: Ignoring SIP message because of retransmit (INVITE Seqno 1, ours 1) [Apr 7 16:46:43] Ignoring this INVITE request [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:13462 handle_request_invite: Got a SIP re-transmit of INVITE for call 116ef430-dd07d2b2-a681586f@172.30.45.130 [Apr 7 16:46:43] <--- SIP read from 172.30.45.130:5060 ---> ACK sip:1990@172.30.32.5 SIP/2.0 Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bKafd8e13e258EF45 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as29d82416 CSeq: 1 ACK Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: ACK sip:1990@172.30.32.5 SIP/2.0 (32) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bKafd8e13e258EF45 (60) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "7111" ;tag=DAD37944-650A6EE9 (57) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as29d82416 (52) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 1 ACK (11) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 (49) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Max-Forwards: 70 (16) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 7 16:46:43] --- (11 headers 0 lines) --- [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:14696 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #11 [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2091 __sip_ack: Stopping retransmission on '116ef430-dd07d2b2-a681586f@172.30.45.130' of Response 1: Match Not Found [Apr 7 16:46:43] <--- SIP read from 172.30.45.130:5060 ---> INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37 From: "7111" ;tag=DAD37944-650A6EE9 To: CSeq: 2 INVITE Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="e355df7ca4c5bd16f05aa34b06b2d331", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1175902012 1175902012 IN IP4 172.30.45.130 s=Polycom IP Phone c=IN IP4 172.30.45.130 t=0 0 m=audio 2230 RTP/AVP 0 18 8 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 (46) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37 (61) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "7111" ;tag=DAD37944-650A6EE9 (57) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: (37) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 2 INVITE (14) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 (49) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="e355df7ca4c5bd16f05aa34b06b2d331", algorithm=MD5 (178) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 12: Max-Forwards: 70 (16) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 13: Content-Type: application/sdp (29) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 14: Content-Length: 251 (19) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 15: (0) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: o=- 1175902012 1175902012 IN IP4 172.30.45.130 (46) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: c=IN IP4 172.30.45.130 (22) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: m=audio 2230 RTP/AVP 0 18 8 101 (31) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 7 16:46:43] --- (15 headers 11 lines) --- [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 7 16:46:43] Sending to 172.30.45.130 : 5060 (NAT) [Apr 7 16:46:43] Using INVITE request as basis request - 116ef430-dd07d2b2-a681586f@172.30.45.130 [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to On [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2582 do_setnat: Setting NAT on VRTP to On [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:2587 do_setnat: Setting NAT on UDPTL to On [Apr 7 16:46:43] Found user '7111' [Apr 7 16:46:43] Found RTP audio format 0 [Apr 7 16:46:43] Found RTP audio format 18 [Apr 7 16:46:43] Found RTP audio format 8 [Apr 7 16:46:43] Found RTP audio format 101 [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:4901 process_sdp: Peer doesn't provide T.38 UDPTL [Apr 7 16:46:43] Peer audio RTP is at port 172.30.45.130:2230 [Apr 7 16:46:43] Found description format PCMU for ID 0 [Apr 7 16:46:43] Found description format G729 for ID 18 [Apr 7 16:46:43] Found description format PCMA for ID 8 [Apr 7 16:46:43] Found description format telephone-event for ID 101 [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:5134 process_sdp: T38 state changed to 0 on channel [Apr 7 16:46:43] Capabilities: us - 0x504 (ulaw|g729|ilbc), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x104 (ulaw|g729) [Apr 7 16:46:43] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 7 16:46:43] Peer audio RTP is at port 172.30.45.130:2230 [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:5214 process_sdp: We're settling with these formats: 0x104 (ulaw|g729) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:13407 handle_request_invite: Checking SIP call limits for device 7111 [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:3005 update_call_counter: Updating call counter for incoming call [Apr 7 16:46:43] Looking for 1990 in test-outb (domain 172.30.32.5) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:3807 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:3808 sip_new: *** Joint capabilities are 0x104 (ulaw|g729) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:3809 sip_new: *** Our capabilities are 0x504 (ulaw|g729|ilbc) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:3810 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:3833 sip_new: This channel will not be able to handle video. [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:7986 build_route: build_route: Contact hop: [Apr 7 16:46:43] list_route: hop: [Apr 7 16:46:43] DEBUG[25349]: chan_sip.c:13482 handle_request_invite: SIP/7111-0a0e5410: New call is still down.... Trying... [Apr 7 16:46:43] <--- Transmitting (NAT) to 172.30.45.130:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 7 16:46:43] DEBUG[25349]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7111-0a0e5410 [Apr 7 16:46:43] DEBUG[25342]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7111 [Apr 7 16:46:43] DEBUG[25342]: chan_sip.c:15308 sip_devicestate: Checking device state for peer 7111 [Apr 7 16:46:43] DEBUG[25342]: devicestate.c:287 do_state_change: Changing state for SIP/7111 - state 1 (Not in use) [Apr 7 16:46:43] DEBUG[25374]: pbx.c:1795 pbx_extension_helper: Launching 'Answer' [Apr 7 16:46:43] DEBUG[25375]: app_queue.c:546 changethread: Device 'SIP/7111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 7 16:46:43] -- Executing [1990@test-outb:1] Answer("SIP/7111-0a0e5410", "") in new stack [Apr 7 16:46:43] DEBUG[25374]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7111-0a0e5410 [Apr 7 16:46:43] DEBUG[25374]: chan_sip.c:3465 sip_answer: SIP answering channel: SIP/7111-0a0e5410 [Apr 7 16:46:43] DEBUG[25342]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7111 [Apr 7 16:46:43] DEBUG[25342]: chan_sip.c:15308 sip_devicestate: Checking device state for peer 7111 [Apr 7 16:46:43] DEBUG[25342]: devicestate.c:287 do_state_change: Changing state for SIP/7111 - state 1 (Not in use) [Apr 7 16:46:43] DEBUG[25376]: app_queue.c:546 changethread: Device 'SIP/7111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 7 16:46:43] DEBUG[25374]: chan_sip.c:6426 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 7 16:46:43] DEBUG[25374]: chan_sip.c:6194 add_sdp: ** Our capability: 0x104 (ulaw|g729) Video flag: True [Apr 7 16:46:43] DEBUG[25374]: chan_sip.c:6195 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 7 16:46:43] Audio is at 172.30.32.5 port 12236 [Apr 7 16:46:43] Adding codec 0x4 (ulaw) to SDP [Apr 7 16:46:43] Adding codec 0x100 (g729) to SDP [Apr 7 16:46:43] Adding non-codec 0x1 (telephone-event) to SDP [Apr 7 16:46:43] DEBUG[25374]: chan_sip.c:6326 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:46:43] DEBUG[25374]: chan_sip.c:6371 add_sdp: Done building SDP. Settling with this capability: 0x104 (ulaw|g729) [Apr 7 16:46:43] <--- Reliably Transmitting (NAT) to 172.30.45.130:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25338 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 7 16:46:43] DEBUG[25374]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #13 [Apr 7 16:46:43] DEBUG[25374]: pbx.c:1795 pbx_extension_helper: Launching 'Echo' [Apr 7 16:46:43] -- Executing [1990@test-outb:2] Echo("SIP/7111-0a0e5410", "") in new stack [Apr 7 16:46:44] <--- SIP read from 172.30.45.130:5060 ---> INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37 From: "7111" ;tag=DAD37944-650A6EE9 To: CSeq: 2 INVITE Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="e355df7ca4c5bd16f05aa34b06b2d331", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1175902012 1175902012 IN IP4 172.30.45.130 s=Polycom IP Phone c=IN IP4 172.30.45.130 t=0 0 m=audio 2230 RTP/AVP 0 18 8 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: INVITE sip:1990@172.30.32.5;user=phone SIP/2.0 (46) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37 (61) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "7111" ;tag=DAD37944-650A6EE9 (57) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: (37) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 2 INVITE (14) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 (49) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="e355df7ca4c5bd16f05aa34b06b2d331", algorithm=MD5 (178) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 12: Max-Forwards: 70 (16) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 13: Content-Type: application/sdp (29) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 14: Content-Length: 251 (19) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 15: (0) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: o=- 1175902012 1175902012 IN IP4 172.30.45.130 (46) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: c=IN IP4 172.30.45.130 (22) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: m=audio 2230 RTP/AVP 0 18 8 101 (31) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 7 16:46:44] --- (15 headers 11 lines) --- [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:14715 handle_request: Ignoring SIP message because of retransmit (INVITE Seqno 2, ours 2) [Apr 7 16:46:44] Ignoring this INVITE request [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:13462 handle_request_invite: Got a SIP re-transmit of INVITE for call 116ef430-dd07d2b2-a681586f@172.30.45.130 [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:13555 handle_request_invite: SIP/7111-0a0e5410: This call is UP.... [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:6426 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:6194 add_sdp: ** Our capability: 0x104 (ulaw|g729) Video flag: True [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:6195 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 7 16:46:44] Audio is at 172.30.32.5 port 12236 [Apr 7 16:46:44] Adding codec 0x4 (ulaw) to SDP [Apr 7 16:46:44] Adding codec 0x100 (g729) to SDP [Apr 7 16:46:44] Adding non-codec 0x1 (telephone-event) to SDP [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:6326 add_sdp: -- Done with adding codecs to SDP [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:6371 add_sdp: Done building SDP. Settling with this capability: 0x104 (ulaw|g729) [Apr 7 16:46:44] <--- Reliably Transmitting (NAT) to 172.30.45.130:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25339 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #14 [Apr 7 16:46:44] DEBUG[25374]: rtp.c:2705 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 7 16:46:44] DEBUG[25374]: rtp.c:2722 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #13 (1) SIP/2.0 - 1 [Apr 7 16:46:44] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #13)) [Apr 7 16:46:44] Retransmitting #1 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25338 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:45] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #14 (1) SIP/2.0 - 1 [Apr 7 16:46:45] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #14)) [Apr 7 16:46:45] Retransmitting #1 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25339 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:45] DEBUG[25374]: rtp.c:2575 ast_rtp_raw_write: Difference is 848, ms is 126 [Apr 7 16:46:45] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #13 (2) SIP/2.0 - 1 [Apr 7 16:46:45] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #13)) [Apr 7 16:46:45] Retransmitting #2 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25338 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:46] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #14 (2) SIP/2.0 - 1 [Apr 7 16:46:46] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #14)) [Apr 7 16:46:46] Retransmitting #2 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25339 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:47] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #13 (3) SIP/2.0 - 1 [Apr 7 16:46:47] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #13)) [Apr 7 16:46:47] Retransmitting #3 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25338 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:48] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #14 (3) SIP/2.0 - 1 [Apr 7 16:46:48] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #14)) [Apr 7 16:46:48] Retransmitting #3 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25339 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:50] DEBUG[25374]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 7 16:46:51] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #13 (4) SIP/2.0 - 1 [Apr 7 16:46:51] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #13)) [Apr 7 16:46:51] Retransmitting #4 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25338 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:52] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #14 (4) SIP/2.0 - 1 [Apr 7 16:46:52] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #14)) [Apr 7 16:46:52] Retransmitting #4 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25339 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:55] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #13 (5) SIP/2.0 - 1 [Apr 7 16:46:55] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #13)) [Apr 7 16:46:55] Retransmitting #5 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25338 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:56] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #14 (5) SIP/2.0 - 1 [Apr 7 16:46:56] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 4000 ms (t1 500 ms (Retrans id #14)) [Apr 7 16:46:56] Retransmitting #5 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25339 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:46:59] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #13 (6) SIP/2.0 - 1 [Apr 7 16:46:59] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #13)) [Apr 7 16:46:59] Retransmitting #6 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25338 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:47:00] DEBUG[25349]: chan_sip.c:1868 retrans_pkt: SIP TIMER: Rescheduling retransmission #14 (6) SIP/2.0 - 1 [Apr 7 16:47:00] DEBUG[25349]: chan_sip.c:1882 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #14)) [Apr 7 16:47:00] Retransmitting #6 (NAT) to 172.30.45.130:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK8552a498E9246F37;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 2 INVITE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 285 v=0 o=root 25338 25339 IN IP4 172.30.32.5 s=session c=IN IP4 172.30.32.5 t=0 0 m=audio 12236 RTP/AVP 0 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 7 16:47:00] DEBUG[25374]: rtp.c:875 ast_rtcp_read: Got RTCP report of 80 bytes [Apr 7 16:47:03] WARNING[25349]: chan_sip.c:1901 retrans_pkt: Maximum retries exceeded on transmission 116ef430-dd07d2b2-a681586f@172.30.45.130 for seqno 2 (Critical Response) [Apr 7 16:47:03] DEBUG[25349]: chan_sip.c:1635 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 116ef430-dd07d2b2-a681586f@172.30.45.130 [Apr 7 16:47:03] WARNING[25349]: chan_sip.c:1918 retrans_pkt: Hanging up call 116ef430-dd07d2b2-a681586f@172.30.45.130 - no reply to our critical packet. [Apr 7 16:47:03] DEBUG[25374]: pbx.c:2393 __ast_pbx_run: Spawn extension (test-outb,1990,2) exited non-zero on 'SIP/7111-0a0e5410' [Apr 7 16:47:03] == Spawn extension (test-outb, 1990, 2) exited non-zero on 'SIP/7111-0a0e5410' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Tim McKee" <7045874829>' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '7045874829' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1990' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'test-outb' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/7111-0a0e5410' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Echo' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-07 16:46:43' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-07 16:46:43' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-07 16:47:03' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '20' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '20' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SDN-ENG' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175964403.0' [Apr 7 16:47:03] DEBUG[25374]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 7 16:47:03] DEBUG[25374]: channel.c:1698 ast_hangup: Hanging up channel 'SIP/7111-0a0e5410' [Apr 7 16:47:03] DEBUG[25374]: chan_sip.c:3314 sip_hangup: Hangup call SIP/7111-0a0e5410, SIP callid 116ef430-dd07d2b2-a681586f@172.30.45.130) [Apr 7 16:47:03] DEBUG[25374]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7111-0a0e5410 [Apr 7 16:47:03] DEBUG[25342]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 7111 [Apr 7 16:47:03] DEBUG[25342]: chan_sip.c:15308 sip_devicestate: Checking device state for peer 7111 [Apr 7 16:47:03] DEBUG[25342]: devicestate.c:287 do_state_change: Changing state for SIP/7111 - state 1 (Not in use) [Apr 7 16:47:03] DEBUG[25377]: app_queue.c:546 changethread: Device 'SIP/7111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 7 16:47:04] WARNING[25349]: chan_sip.c:1901 retrans_pkt: Maximum retries exceeded on transmission 116ef430-dd07d2b2-a681586f@172.30.45.130 for seqno 2 (Critical Response) [Apr 7 16:47:04] Really destroying SIP dialog '116ef430-dd07d2b2-a681586f@172.30.45.130' Method: INVITE [Apr 7 16:47:15] <--- SIP read from 172.30.45.130:5060 ---> BYE sip:1990@172.30.32.5 SIP/2.0 Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK21717155E4A0FE00 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 CSeq: 3 BYE Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 Contact: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="5191400b1ea4f7c717fef1a4148fbcd7", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: BYE sip:1990@172.30.32.5 SIP/2.0 (32) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK21717155E4A0FE00 (61) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "7111" ;tag=DAD37944-650A6EE9 (57) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as73b7cba8 (52) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 3 BYE (11) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 (49) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="5191400b1ea4f7c717fef1a4148fbcd7", algorithm=MD5 (178) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Max-Forwards: 70 (16) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 7 16:47:15] --- (11 headers 0 lines) --- [Apr 7 16:47:15] <--- Transmitting (NAT) to 172.30.45.130:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK21717155E4A0FE00;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 3 BYE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:14880 sipsock_read: Invalid SIP message - rejected , no callid, len 584 [Apr 7 16:47:15] <--- SIP read from 172.30.45.130:5060 ---> BYE sip:1990@172.30.32.5 SIP/2.0 Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK21717155E4A0FE00 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 CSeq: 3 BYE Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 Contact: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="5191400b1ea4f7c717fef1a4148fbcd7", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: BYE sip:1990@172.30.32.5 SIP/2.0 (32) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK21717155E4A0FE00 (61) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "7111" ;tag=DAD37944-650A6EE9 (57) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as73b7cba8 (52) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 3 BYE (11) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 (49) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: Proxy-Authorization: Digest username="7111", realm="asterisk", nonce="19751752", uri="sip:1990@172.30.32.5;user=phone", response="5191400b1ea4f7c717fef1a4148fbcd7", algorithm=MD5 (178) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Max-Forwards: 70 (16) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 7 16:47:15] --- (11 headers 0 lines) --- [Apr 7 16:47:15] <--- Transmitting (NAT) to 172.30.45.130:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 172.30.45.130;branch=z9hG4bK21717155E4A0FE00;received=172.30.45.130 From: "7111" ;tag=DAD37944-650A6EE9 To: ;tag=as73b7cba8 Call-ID: 116ef430-dd07d2b2-a681586f@172.30.45.130 CSeq: 3 BYE User-Agent: SDN Global PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Apr 7 16:47:15] DEBUG[25349]: chan_sip.c:14880 sipsock_read: Invalid SIP message - rejected , no callid, len 584 [Apr 7 16:47:40] DEBUG[25351]: chan_iax2.c:7112 socket_process: Peer pbx01: got pong, lastms 7, historicms 7, maxms 5000 [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: OPTIONS sip:7111@172.30.45.130 SIP/2.0 (38) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK26c57b89;rport (62) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as134ee169 (58) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: (28) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: Contact: (35) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 4cba33741864cdde08bcdca720465f97@172.30.32.5 (53) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: User-Agent: SDN Global PBX (26) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Date: Sat, 07 Apr 2007 16:47:42 GMT (35) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 11: Supported: replaces (19) [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 12: Content-Length: 0 (17) [Apr 7 16:47:42] Reliably Transmitting (NAT) to 172.30.45.130:5060: OPTIONS sip:7111@172.30.45.130 SIP/2.0 Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK26c57b89;rport From: "asterisk" ;tag=as134ee169 To: Contact: Call-ID: 4cba33741864cdde08bcdca720465f97@172.30.32.5 CSeq: 102 OPTIONS User-Agent: SDN Global PBX Max-Forwards: 70 Date: Sat, 07 Apr 2007 16:47:42 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 7 16:47:42] DEBUG[25349]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #16 [Apr 7 16:47:43] <--- SIP read from 172.30.45.130:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK26c57b89;rport From: "asterisk" ;tag=as134ee169 To: ;tag=510AD5F9-E0EA4B02 CSeq: 102 OPTIONS Call-ID: 4cba33741864cdde08bcdca720465f97@172.30.32.5 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 Content-Length: 0 <-------------> [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 172.30.32.5:5060;branch=z9hG4bK26c57b89;rport (62) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as134ee169 (58) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=510AD5F9-E0EA4B02 (50) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 4: CSeq: 102 OPTIONS (17) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 4cba33741864cdde08bcdca720465f97@172.30.32.5 (53) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 6: Contact: (33) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_601-UA/2.0.3.0127 (54) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 9: Content-Length: 0 (17) [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:4575 parse_request: Header 10: (0) [Apr 7 16:47:43] --- (10 headers 0 lines) --- [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #16 [Apr 7 16:47:43] DEBUG[25349]: chan_sip.c:2091 __sip_ack: Stopping retransmission on '4cba33741864cdde08bcdca720465f97@172.30.32.5' of Request 102: Match Not Found [Apr 7 16:47:43] Really destroying SIP dialog '4cba33741864cdde08bcdca720465f97@172.30.32.5' Method: OPTIONS *CLI> exit No such command 'exit' (type 'help' for help) *CLI> quit No such command 'quit' (type 'help' for help) *CLI> exit No such command 'exit' (type 'help' for help) *CLI> help ! Execute a shell command abort halt Cancel a running halt ael debug contexts Enable AEL contexts debug (does nothing) ael debug macros Enable AEL macros debug (does nothing) ael debug read Enable AEL read debug (does nothing) ael debug tokens Enable AEL tokens debug (does nothing) ael nodebug Disable AEL debug messages ael reload Reload AEL configuration agent logoff Sets an agent offline agent show Show status of agents agent show online Show all online agents agi debug Enable AGI debugging agi debug off Disable AGI debugging agi dumphtml Dumps a list of agi commands in html format agi show List AGI commands or specific help cdr status Display the CDR status console active Sets/displays active console console answer Answer an incoming console call console autoanswer Sets/displays autoanswer console boost Sets/displays mic boost in dB console dial Dial an extension on the console console flash Flash a call on the console console hangup Hangup a call on the console console mute Disable mic input console send text Send text to the remote device console transfer Transfer a call to a different extension console unmute Enable mic input core clear profile Clear profiling info core set debug channel Enable/disable debugging on a channel core set debug Set level of debug chattiness core set debug off Turns off debug chattiness core set global Set global dialplan variable core set verbose Set level of verboseness core show applications Shows registered dialplan applications core show application Describe a specific dialplan application core show audio codecs Displays a list of audio codecs core show channels Display information on channels core show channel Display information on a specific channel core show channeltypes List available channel types core show channeltype Give more details on that channel type core show codecs Displays a list of codecs core show codec Shows a specific codec core show config mappings Display config mappings (file names to config engines) core show file formats Displays file formats core show file version List versions of files used to build Asterisk core show functions Shows registered dialplan functions core show function Describe a specific dialplan function core show globals Show global dialplan variables core show hints Show dialplan hints core show image codecs Displays a list of image codecs core show image formats Displays image formats core show license Show the license(s) for this copy of Asterisk core show profile Display profiling info core show switches Show alternative switches core show threads Show running threads core show translation Display translation matrix core show uptime Show uptime information core show version Display version info core show video codecs Displays a list of video codecs core show warranty Show the warranty (if any) for this copy of Asterisk database del Removes database key/value database deltree Removes database keytree/values database get Gets database value database put Adds/updates database value database show Shows database contents database showkey Shows database contents dialplan add extension Add new extension into context dialplan add ignorepat Add new ignore pattern dialplan add include Include context in other context dialplan reload Reload extensions and *only* extensions dialplan remove extension Remove a specified extension dialplan remove ignorepat Remove ignore pattern from context dialplan remove include Remove a specified include from context dialplan save Save dialplan dialplan show Show dialplan dnsmgr reload Reloads the DNS manager configuration dnsmgr status Display the DNS manager status dundi debug Enable DUNDi debugging dundi flush Flush DUNDi cache dundi lookup Lookup a number in DUNDi dundi no debug Disable DUNDi debugging dundi no store history Disable DUNDi historic records dundi precache Precache a number in DUNDi dundi query Query a DUNDi EID dundi show entityid Display Global Entity ID dundi show mappings Show DUNDi mappings dundi show peers Show defined DUNDi peers dundi show peer Show info on a specific DUNDi peer dundi show precache Show DUNDi precache dundi show requests Show DUNDi requests dundi show trans Show active DUNDi transactions dundi store history Enable DUNDi historic records feature show Lists configured features feature show channels List status of feature channels file convert Convert audio file group show channels Display active channels with group(s) help Display help list, or specific help on a command http show status Display HTTP server status iax2 provision Provision an IAX device iax2 prune realtime Prune a cached realtime lookup iax2 reload Reload IAX configuration iax2 set debug Enable IAX debugging iax2 set debug jb Enable IAX jitterbuffer debugging iax2 set debug jb off Disable IAX jitterbuffer debugging iax2 set debug off Disable IAX debugging iax2 set debug trunk Enable IAX trunk debugging iax2 set debug trunk off Disable IAX trunk debugging iax2 show cache Display IAX cached dialplan iax2 show channels List active IAX channels iax2 show firmware List available IAX firmwares iax2 show netstats List active IAX channel netstats iax2 show peers List defined IAX peers iax2 show peer Show details on specific IAX peer iax2 show provisioning Display iax provisioning iax2 show registry Display IAX registration status iax2 show stats Display IAX statistics iax2 show threads Display IAX helper thread info iax2 show users List defined IAX users iax2 test losspct Set IAX2 incoming frame loss percentage indication add Add the given indication to the country indication remove Remove the given indication from the country indication show Display a list of all countries/indications keys init Initialize RSA key passcodes keys show Displays RSA key information local show channels List status of local channels logger mute Toggle logging output to a console logger reload Reopens the log files logger rotate Rotates and reopens the log files logger show channels List configured log channels manager show command Show a manager interface command manager show commands List manager interface commands manager show connected List connected manager interface users manager show eventq List manager interface queued events manager show users List configured manager users manager show user Display information on a specific manager user meetme Execute a command on a conference or conferee mgcp audit endpoint Audit specified MGCP endpoint mgcp reload Reload MGCP configuration mgcp set debug Enable MGCP debugging mgcp set debug off Disable MGCP debugging mgcp show endpoints List defined MGCP endpoints mixmonitor Execute a MixMonitor command. module load Load a module by name module reload Reload configuration module show List modules and info module show like List modules and info module unload Unload a module by name moh reload Music On Hold moh show classes List MOH classes moh show files List MOH file-based classes no debug channel (null) originate Originate a call pri debug span Enables PRI debugging on a span pri intense debug span Enables REALLY INTENSE PRI debugging pri no debug span Disables PRI debugging on a span pri set debug file Sends PRI debug output to the specified file pri show debug Displays current PRI debug settings pri show spans Displays PRI Information pri show span Displays PRI Information pri unset debug file Ends PRI debug output to file queue add member Add a channel to a specified queue queue remove member Removes a channel from a specified queue queue show Show status of a specified queue realtime load Used to print out RealTime variables. realtime mysql status Shows connection information for the MySQL RealTime driver realtime update Used to update RealTime variables. restart gracefully Restart Asterisk gracefully restart now Restart Asterisk immediately restart when convenient Restart Asterisk at empty call volume rtcp debug ip Enable RTCP debugging on IP rtcp debug Enable RTCP debugging rtcp debug off Disable RTCP debugging rtcp stats Enable RTCP stats rtcp stats off Disable RTCP stats rtp debug ip Enable RTP debugging on IP rtp debug Enable RTP debugging rtp debug off Disable RTP debugging say load set/show the say mode show g729 Show G.729 Usage show parkedcalls Lists parked calls show queues (null) sip history Enable SIP history sip history off Disable SIP history sip notify Send a notify packet to a SIP peer sip prune realtime Prune cached Realtime object(s) sip prune realtime peer Prune cached Realtime peer(s) sip prune realtime user Prune cached Realtime user(s) sip reload Reload SIP configuration sip set debug Enable SIP debugging sip set debug ip Enable SIP debugging on IP sip set debug off Disable SIP debugging sip set debug peer Enable SIP debugging on Peername sip show channels List active SIP channels sip show channel Show detailed SIP channel info sip show domains List our local SIP domains. sip show history Show SIP dialog history sip show inuse List all inuse/limits sip show objects List all SIP object allocations sip show peers List defined SIP peers sip show peer Show details on specific SIP peer sip show registry List SIP registration status sip show settings Show SIP global settings sip show subscriptions List active SIP subscriptions sip show users List defined SIP users sip show user Show details on specific SIP user skinny reset Reset Skinny device(s) skinny set debug Enable Skinny debugging skinny set debug off Disable Skinny debugging skinny show devices List defined Skinny devices skinny show lines List defined Skinny lines per device sla show stations Show SLA Stations sla show trunks Show SLA Trunks soft hangup Request a hangup on a given channel stop gracefully Gracefully shut down Asterisk stop now Shut down Asterisk immediately stop when convenient Shut down Asterisk at empty call volume stun debug Enable STUN debugging stun debug off Disable STUN debugging udptl debug Enable UDPTL debugging udptl debug ip Enable UDPTL debugging on IP udptl debug off Disable UDPTL debugging voicemail show users List defined voicemail boxes voicemail show zones List zone message formats zap destroy channel Destroy a channel zap restart Fully restart zaptel channels zap show cadences List cadences zap show channels Show active zapata channels zap show channel Show information on a channel zap show status Show all Zaptel cards status *CLI> stop now [Apr 7 16:48:14] Beginning asterisk shutdown.... [Apr 7 16:48:14] Executing last minute cleanups [Apr 7 16:48:14] == Destroying musiconhold processes [Apr 7 16:48:14] Asterisk cleanly ending (0). [Apr 7 16:48:14] DEBUG[25338]: asterisk.c:1276 quit_handler: Asterisk ending (0).