[Aug 9 14:19:35] VERBOSE[4402] config.c: == Parsing '/etc/asterisk/logger.conf': [Aug 9 14:19:35] DEBUG[4402] config.c: Parsing /etc/asterisk/logger.conf [Aug 9 14:19:35] VERBOSE[4402] config.c: == Found [Aug 9 14:19:35] VERBOSE[4402] logger.c: Asterisk Queue Logger restarted [Aug 9 14:19:35] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:35] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:36] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:36] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:37] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:37] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:38] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:38] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:39] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:39] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: <--- SIP read from UDP:10.13.22.63:5060 ---> INVITE sip:6000@10.21.0.146:5061;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bKe46f124cCE853995 From: "4709" ;tag=54B65261-741E19AE To: CSeq: 1 INVITE Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439 Accept-Language: en Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 292 v=0 o=- 1168027763 1168027763 IN IP4 10.13.22.63 s=Polycom IP Phone c=IN IP4 10.13.22.63 t=0 0 a=sendrecv m=audio 2244 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 <-------------> [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 0 [ 51]: INVITE sip:6000@10.21.0.146:5061;user=phone SIP/2.0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bKe46f124cCE853995 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 2 [ 57]: From: "4709" ;tag=54B65261-741E19AE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 3 [ 37]: To: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 5 [ 47]: Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 6 [ 31]: Contact: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 10 [ 26]: Supported: 100rel,replaces [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 11 [ 34]: Allow-Events: talk,hold,conference [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 12 [ 16]: Max-Forwards: 70 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 14 [ 19]: Content-Length: 292 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 15 [ 0]: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 0 [ 3]: v=0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 1 [ 44]: o=- 1168027763 1168027763 IN IP4 10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 2 [ 18]: s=Polycom IP Phone [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 4 [ 5]: t=0 0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 5 [ 10]: a=sendrecv [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 6 [ 33]: m=audio 2244 RTP/AVP 9 0 8 18 101 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 7 [ 20]: a=rtpmap:9 G722/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 10 [ 21]: a=rtpmap:18 G729/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 11 [ 19]: a=fmtp:18 annexb=no [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: --- (15 headers 13 lines) --- [Aug 9 14:19:40] DEBUG[31464] acl.c: For destination '10.13.22.63', our source address is '10.21.0.146'. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.21.0.146:5061 [Aug 9 14:19:40] VERBOSE[31464] netsock.c: == Using UDPTL CoS mark 5 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Setting NAT on UDPTL to Off [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Allocating new SIP dialog for 631c0e72-5cfe31f3-d0c98868@10.13.22.63 - INVITE (No RTP) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Aug 9 14:19:40] DEBUG[31464] sip/reqresp_parser.c: Begin: parsing SIP "Supported: 100rel,replaces" [Aug 9 14:19:40] DEBUG[31464] sip/reqresp_parser.c: Found SIP option: -100rel- [Aug 9 14:19:40] DEBUG[31464] sip/reqresp_parser.c: Matched SIP option: 100rel [Aug 9 14:19:40] DEBUG[31464] sip/reqresp_parser.c: Found SIP option: -replaces- [Aug 9 14:19:40] DEBUG[31464] sip/reqresp_parser.c: Matched SIP option: replaces [Aug 9 14:19:40] DEBUG[31464] netsock2.c: Splitting '10.13.22.63' gives... [Aug 9 14:19:40] DEBUG[31464] netsock2.c: ...host '10.13.22.63' and port '(null)'. [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Sending to 10.13.22.63:5060 (no NAT) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Initializing initreq for method INVITE - callid 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Using INVITE request as basis request - 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found peer '4709' for '4709' from 10.13.22.63:5060 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Setting NAT on UDPTL to Off [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: <--- Reliably Transmitting (no NAT) to 10.13.22.63:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bKe46f124cCE853995;received=10.13.22.63 From: "4709" ;tag=54B65261-741E19AE To: ;tag=as60790dfb Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 CSeq: 1 INVITE Server: Asterisk PBX 1.8.0-beta2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5722e4a4" Content-Length: 0 <------------> [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5045 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.13.22.63:5060 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Scheduling destruction of SIP dialog '631c0e72-5cfe31f3-d0c98868@10.13.22.63' in 32000 ms (Method: INVITE) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: <--- SIP read from UDP:10.13.22.63:5060 ---> ACK sip:6000@10.21.0.146:5061 SIP/2.0 Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bKe46f124cCE853995 From: "4709" ;tag=54B65261-741E19AE To: ;tag=as60790dfb CSeq: 1 ACK Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439 Accept-Language: en Max-Forwards: 70 Content-Length: 0 <-------------> [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 0 [ 37]: ACK sip:6000@10.21.0.146:5061 SIP/2.0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bKe46f124cCE853995 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 2 [ 57]: From: "4709" ;tag=54B65261-741E19AE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 3 [ 52]: To: ;tag=as60790dfb [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 4 [ 11]: CSeq: 1 ACK [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 5 [ 47]: Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 6 [ 31]: Contact: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 12 [ 0]: [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: --- (12 headers 0 lines) --- [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5045 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Stopping retransmission on '631c0e72-5cfe31f3-d0c98868@10.13.22.63' of Response 1: Match Found [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: <--- SIP read from UDP:10.13.22.63:5060 ---> INVITE sip:6000@10.21.0.146:5061;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bK95c8825fAB8B4FC4 From: "4709" ;tag=54B65261-741E19AE To: CSeq: 2 INVITE Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439 Accept-Language: en Supported: 100rel,replaces Allow-Events: talk,hold,conference Authorization: Digest username="4709", realm="asterisk", nonce="5722e4a4", uri="sip:6000@10.21.0.146:5061;user=phone", response="7436e26fc14eca1091e974565b65031c", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 292 v=0 o=- 1168027763 1168027763 IN IP4 10.13.22.63 s=Polycom IP Phone c=IN IP4 10.13.22.63 t=0 0 a=sendrecv m=audio 2244 RTP/AVP 9 0 8 18 101 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 <-------------> [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 0 [ 51]: INVITE sip:6000@10.21.0.146:5061;user=phone SIP/2.0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bK95c8825fAB8B4FC4 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 2 [ 57]: From: "4709" ;tag=54B65261-741E19AE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 3 [ 37]: To: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 4 [ 14]: CSeq: 2 INVITE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 5 [ 47]: Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 6 [ 31]: Contact: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 10 [ 26]: Supported: 100rel,replaces [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 11 [ 34]: Allow-Events: talk,hold,conference [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 12 [177]: Authorization: Digest username="4709", realm="asterisk", nonce="5722e4a4", uri="sip:6000@10.21.0.146:5061;user=phone", response="7436e26fc14eca1091e974565b65031c", algorithm=MD5 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 13 [ 16]: Max-Forwards: 70 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 15 [ 19]: Content-Length: 292 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Header 16 [ 0]: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 0 [ 3]: v=0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 1 [ 44]: o=- 1168027763 1168027763 IN IP4 10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 2 [ 18]: s=Polycom IP Phone [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 4 [ 5]: t=0 0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 5 [ 10]: a=sendrecv [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 6 [ 33]: m=audio 2244 RTP/AVP 9 0 8 18 101 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 7 [ 20]: a=rtpmap:9 G722/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 9 [ 20]: a=rtpmap:8 PCMA/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 10 [ 21]: a=rtpmap:18 G729/8000 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 11 [ 19]: a=fmtp:18 annexb=no [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Body 12 [ 33]: a=rtpmap:101 telephone-event/8000 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: --- (16 headers 13 lines) --- [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Aug 9 14:19:40] DEBUG[31464] netsock2.c: Splitting '10.13.22.63' gives... [Aug 9 14:19:40] DEBUG[31464] netsock2.c: ...host '10.13.22.63' and port '(null)'. [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Sending to 10.13.22.63:5060 (no NAT) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Initializing initreq for method INVITE - callid 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Using INVITE request as basis request - 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found peer '4709' for '4709' from 10.13.22.63:5060 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Setting NAT on UDPTL to Off [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xa287030' [Aug 9 14:19:40] DEBUG[31464] res_rtp_asterisk.c: Allocated port 14078 for RTP instance '0xa287030' [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: RTP instance '0xa287030' is setup and ready to go [Aug 9 14:19:40] DEBUG[31464] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xa287030' [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Setting NAT on RTP to Off [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Setting NAT on UDPTL to Off [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing session-level SDP o=- 1168027763 1168027763 IN IP4 10.13.22.63... UNSUPPORTED. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED. [Aug 9 14:19:40] DEBUG[31464] netsock2.c: Splitting '10.13.22.63' gives... [Aug 9 14:19:40] DEBUG[31464] netsock2.c: ...host '10.13.22.63' and port '(null)'. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing session-level SDP c=IN IP4 10.13.22.63... OK. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing session-level SDP a=sendrecv... OK. [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found RTP audio format 9 [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Setting payload 9 based on m type on 0xb7cd83cc [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found RTP audio format 0 [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Setting payload 0 based on m type on 0xb7cd83cc [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found RTP audio format 8 [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Setting payload 8 based on m type on 0xb7cd83cc [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found RTP audio format 18 [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Setting payload 18 based on m type on 0xb7cd83cc [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found RTP audio format 101 [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Setting payload 101 based on m type on 0xb7cd83cc [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found audio description format G722 for ID 9 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found audio description format PCMU for ID 0 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found audio description format PCMA for ID 8 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found audio description format G729 for ID 18 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Found audio description format telephone-event for ID 101 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Incorporating payload 0 on 0xb7cd83cc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Incorporating payload 8 on 0xb7cd83cc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Incorporating payload 9 on 0xb7cd83cc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Incorporating payload 18 on 0xb7cd83cc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Incorporating payload 101 on 0xb7cd83cc [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Capabilities: us - 0x100c (ulaw|alaw|g722), peer - audio=0x110c (ulaw|alaw|g729|g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x100c (ulaw|alaw|g722) [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Aug 9 14:19:40] DEBUG[31464] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xa287030' [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Peer audio RTP is at port 10.13.22.63:2244 [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Copying payload 0 from 0xb7cd83cc to 0xa2871dc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Copying payload 8 from 0xb7cd83cc to 0xa2871dc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Copying payload 9 from 0xb7cd83cc to 0xa2871dc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Copying payload 18 from 0xb7cd83cc to 0xa2871dc [Aug 9 14:19:40] DEBUG[31464] rtp_engine.c: Copying payload 101 from 0xb7cd83cc to 0xa2871dc [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Peer doesn't provide T.38 UDPTL [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: We're settling with these formats: 0x1000 (g722) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Checking SIP call limits for device 4709 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Updating call counter for incoming call [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Call from peer '4709' is 1 out of 6 [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: Looking for 6000 in DLPN_DialPlanAll (domain 10.21.0.146:5061) [Aug 9 14:19:40] DEBUG[31464] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[31458] devicestate.c: No provider found, checking channel drivers for SIP - 4709 [Aug 9 14:19:40] DEBUG[31458] chan_sip.c: Checking device state for peer 4709 [Aug 9 14:19:40] DEBUG[31458] devicestate.c: Changing state for SIP/4709 - state 2 (In use) [Aug 9 14:19:40] DEBUG[31458] devicestate.c: device 'SIP/4709' state '2' [Aug 9 14:19:40] DEBUG[31464] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa290628 Query: SELECT * FROM extensions_table WHERE exten = '6000' AND context = 'ringgroups' AND priority = '1' [Aug 9 14:19:40] DEBUG[31464] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table extensions_table@asterisk. [Aug 9 14:19:40] DEBUG[31464] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[31464] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa40b180 Query: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'ringgroups' AND priority = '1' ORDER BY exten [Aug 9 14:19:40] DEBUG[31464] res_config_pgsql.c: PostgreSQL RealTime: Could not find any rows in table extensions_table. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: *** Our native formats are 0x1000 (g722) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: *** Joint capabilities are 0x1000 (g722) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: *** Our capabilities are 0x100c (ulaw|alaw|g722) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x1000 (g722) [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: This channel will not be able to handle video. [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: build_route: Contact hop: [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: list_route: hop: [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Session timer started: 5047 - 631c0e72-5cfe31f3-d0c98868@10.13.22.63 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: SIP/4709-00000056: New call is still down.... Trying... [Aug 9 14:19:40] VERBOSE[31464] chan_sip.c: <--- Transmitting (no NAT) to 10.13.22.63:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bK95c8825fAB8B4FC4;received=10.13.22.63 From: "4709" ;tag=54B65261-741E19AE To: Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 CSeq: 2 INVITE Server: Asterisk PBX 1.8.0-beta2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.13.22.63:5060 [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:40] DEBUG[31458] devicestate.c: No provider found, checking channel drivers for SIP - 4709 [Aug 9 14:19:40] DEBUG[31458] chan_sip.c: Checking device state for peer 4709 [Aug 9 14:19:40] DEBUG[31458] devicestate.c: Changing state for SIP/4709 - state 2 (In use) [Aug 9 14:19:40] DEBUG[31458] devicestate.c: device 'SIP/4709' state '2' [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa4421f8 Query: SELECT * FROM extensions_table WHERE exten = '6000' AND context = 'ringgroups' AND priority = '1' [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table extensions_table@asterisk. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa2be740 Query: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'ringgroups' AND priority = '1' ORDER BY exten [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Could not find any rows in table extensions_table. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa1e3ce8 Query: SELECT * FROM extensions_table WHERE exten = '6000' AND context = 'ringgroups' AND priority = '1' [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table extensions_table@asterisk. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa35d9e8 Query: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'ringgroups' AND priority = '1' ORDER BY exten [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Could not find any rows in table extensions_table. [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'EXTEN' is '6000' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [6000@DLPN_DialPlanAll:1] Set("SIP/4709-00000056", "DN=6000") in new stack [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa2be740 Query: SELECT * FROM extensions_table WHERE exten = '6000' AND context = 'ringgroups' AND priority = '2' [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table extensions_table@asterisk. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa40b180 Query: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'ringgroups' AND priority = '2' ORDER BY exten [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Could not find any rows in table extensions_table. [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is 'PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [6000@DLPN_DialPlanAll:2] Set("SIP/4709-00000056", "UserAgent=PolycomSoundPointIP-SPIP_450-UA/3.1.3.0439") in new stack [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa1e3ce8 Query: SELECT * FROM extensions_table WHERE exten = '6000' AND context = 'ringgroups' AND priority = '3' [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table extensions_table@asterisk. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa4421f8 Query: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'ringgroups' AND priority = '3' ORDER BY exten [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Could not find any rows in table extensions_table. [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [6000@DLPN_DialPlanAll:3] Set("SIP/4709-00000056", "CountReq=0") in new stack [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa1e3ce8 Query: SELECT * FROM extensions_table WHERE exten = '6000' AND context = 'ringgroups' AND priority = '4' [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: Postgresql RealTime: Could not find any rows in table extensions_table@asterisk. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: One or more of the parameters in the config does not pass our validity checks. [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Result=0xa35d9e8 Query: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'ringgroups' AND priority = '4' ORDER BY exten [Aug 9 14:19:40] DEBUG[4418] res_config_pgsql.c: PostgreSQL RealTime: Could not find any rows in table extensions_table. [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Macro' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [6000@DLPN_DialPlanAll:4] Macro("SIP/4709-00000056", "DialProcess") in new stack [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'CountReq' is '0' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Expression result is '1' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-DialProcess:1] Set("SIP/4709-00000056", "CountReq=1") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'CountReq' is '1' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Expression result is '0' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'GotoIf' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-DialProcess:2] GotoIf("SIP/4709-00000056", "0?1-End,1") in new stack [Aug 9 14:19:40] DEBUG[4418] pbx.c: Not taking any branch [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: GotoIf [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'WINIP' is '10.21.0.133:8090' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'DN' is '6000' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '4709' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'PermissionExt' is NULL [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'Provider' is NULL [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is 'Polycom' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is 'Polycom' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'IsForward' is NULL [Aug 9 14:19:40] DEBUG[4418] func_curl.c: Called with data=0xb7b3cab8, str=0xa1e3e30, realsize=50, len=16, used=0 [Aug 9 14:19:40] DEBUG[4418] func_curl.c: Now, len=64, used=50 [Aug 9 14:19:40] DEBUG[4418] func_curl.c: str='6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-DialProcess:3] Set("SIP/4709-00000056", "RuleResult=6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'DEF_LANG_PREFIX' is 'ru' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-DialProcess:4] Set("SIP/4709-00000056", "CHANNEL(language)=ru") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Evaluating 'RuleResult' (from 'RuleResult}' len 10) [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'RuleResult' is '6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is 'internal' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-DialProcess:5] Set("SIP/4709-00000056", "CommandType=internal") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Evaluating 'RuleResult' (from 'RuleResult}' len 10) [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'RuleResult' is '6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-DialProcess:6] Set("SIP/4709-00000056", "Announc=") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'Announc' is '' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '0' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Expression result is '1' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'GotoIf' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-DialProcess:7] GotoIf("SIP/4709-00000056", "1?1-Switch,1") in new stack [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Goto (macro-DialProcess,1-Switch,1) [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: GotoIf [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'CommandType' is 'internal' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Expression result is '1' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'GotoIf' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [1-Switch@macro-DialProcess:1] GotoIf("SIP/4709-00000056", "1?1-Internal,1") in new stack [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Goto (macro-DialProcess,1-Internal,1) [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: GotoIf [Aug 9 14:19:40] DEBUG[4418] pbx.c: Evaluating 'RuleResult' (from 'RuleResult}' len 10) [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'RuleResult' is '6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '6000:6000::' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Evaluating 'RuleResult' (from 'RuleResult}' len 10) [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'RuleResult' is '6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '${DEFTIMEOUT}' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'DEFTIMEOUT' is '20' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '20' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Macro' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [1-Internal@macro-DialProcess:1] Macro("SIP/4709-00000056", "Dial-Local,6000:6000::,20") in new stack [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'NoOp' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-Dial-Local:1] NoOp("SIP/4709-00000056", "Dial-Local") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Noop [Aug 9 14:19:40] DEBUG[4418] pbx.c: Evaluating 'ARG1' (from 'ARG1}' len 4) [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'ARG1' is '6000:6000::' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '6000' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-Dial-Local:2] Set("SIP/4709-00000056", "MyDN=6000") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Evaluating 'RuleResult' (from 'RuleResult}' len 10) [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'RuleResult' is '6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is '4709' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-Dial-Local:3] Set("SIP/4709-00000056", "CALLERID(num)=4709") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Evaluating 'RuleResult' (from 'RuleResult}' len 10) [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'RuleResult' is '6000:6000::#4709#Polycom#internal#${DEFTIMEOUT}###' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Function result is 'Polycom' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-Dial-Local:4] Set("SIP/4709-00000056", "CALLERID(name)=Polycom") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'MyDN' is '6000' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Set' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-Dial-Local:5] Set("SIP/4709-00000056", "__PICKUPMARK=6000") in new stack [Aug 9 14:19:40] DEBUG[4418] app_macro.c: Executed application: Set [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'MyDN' is '6000' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Result of 'ARG2' is '20' [Aug 9 14:19:40] DEBUG[4418] pbx.c: Launching 'Dial' [Aug 9 14:19:40] VERBOSE[4418] pbx.c: -- Executing [s@macro-Dial-Local:6] Dial("SIP/4709-00000056", "SIP/6000,20") in new stack [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Asked to create a SIP channel with formats: 0x1000 (g722) [Aug 9 14:19:40] VERBOSE[4418] netsock.c: == Using UDPTL CoS mark 5 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Allocating new SIP dialog for 5b71147430092cba70dd0b880ce0250b@127.0.0.1:0 - INVITE (No RTP) [Aug 9 14:19:40] DEBUG[4418] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xa1ba158' [Aug 9 14:19:40] DEBUG[4418] res_rtp_asterisk.c: Allocated port 13894 for RTP instance '0xa1ba158' [Aug 9 14:19:40] DEBUG[4418] rtp_engine.c: RTP instance '0xa1ba158' is setup and ready to go [Aug 9 14:19:40] DEBUG[4418] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xa1ba158' [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Setting NAT on RTP to Off [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Setting NAT on UDPTL to Off [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Aug 9 14:19:40] DEBUG[4418] acl.c: For destination '10.13.22.38', our source address is '10.21.0.146'. [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.21.0.146:5061 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: *** Our native formats are 0x8 (alaw) [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: *** Our preferred formats from the incoming channel are 0x1000 (g722) [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: This channel will not be able to handle video. [Aug 9 14:19:40] DEBUG[4418] rtp_engine.c: Seeded SDP of 'SIP/6000-00000057' with that of 'SIP/4709-00000056' [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable DIALEDTIME. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable ANSWEREDTIME. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable DIALEDPEERNAME. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable DIALEDPEERNUMBER. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable DIALSTATUS. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable MACRO_DEPTH. [Aug 9 14:19:40] DEBUG[4418] channel.c: Copying hard-transferable variable PICKUPMARK. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable MyDN. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable ARG2. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable ARG1. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable MACRO_PRIORITY. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable MACRO_CONTEXT. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable MACRO_EXTEN. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable Announc. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable CommandType. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable RuleResult. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable CountReq. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable UserAgent. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable DN. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable SIPCALLID. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable SIPDOMAIN. [Aug 9 14:19:40] DEBUG[4418] channel.c: Not copying variable SIPURI. [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Outgoing Call for 6000 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Updating call counter for outgoing call [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Call to peer '6000' is 2 out of 6 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: False [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: ** Our prefcodec: 0x1000 (g722) [Aug 9 14:19:40] VERBOSE[4418] chan_sip.c: Audio is at 5061 [Aug 9 14:19:40] VERBOSE[4418] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Aug 9 14:19:40] VERBOSE[4418] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Aug 9 14:19:40] VERBOSE[4418] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: -- Done with adding codecs to SDP [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Initializing initreq for method INVITE - callid 02f603a20277b5503604fba839fa3fd3@10.21.0.146:5061 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 0 [ 40]: INVITE sip:6000@10.13.22.38:5060 SIP/2.0 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK74b70e26 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 3 [ 58]: From: "Polycom" ;tag=as3d001dbc [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 4 [ 31]: To: [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 5 [ 36]: Contact: [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 6 [ 58]: Call-ID: 02f603a20277b5503604fba839fa3fd3@10.21.0.146:5061 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.8.0-beta2 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 9 [ 35]: Date: Mon, 09 Aug 2010 11:19:40 GMT [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 10 [ 21]: Session-Expires: 1800 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 11 [ 10]: Min-SE: 90 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 12 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:40] DEBUG[31458] devicestate.c: No provider found, checking channel drivers for SIP - 6000 [Aug 9 14:19:40] DEBUG[31458] chan_sip.c: Checking device state for peer 6000 [Aug 9 14:19:40] DEBUG[31458] devicestate.c: Changing state for SIP/6000 - state 7 (Ring+Inuse) [Aug 9 14:19:40] DEBUG[31458] devicestate.c: device 'SIP/6000' state '7' [Aug 9 14:19:40] VERBOSE[4418] chan_sip.c: Reliably Transmitting (no NAT) to 10.13.22.38:5060: INVITE sip:6000@10.13.22.38:5060 SIP/2.0 Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK74b70e26 Max-Forwards: 70 From: "Polycom" ;tag=as3d001dbc To: Contact: Call-ID: 02f603a20277b5503604fba839fa3fd3@10.21.0.146:5061 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.0-beta2 Date: Mon, 09 Aug 2010 11:19:40 GMT Session-Expires: 1800 Min-SE: 90 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 289 v=0 o=root 1093359427 1093359427 IN IP4 10.21.0.146 s=Asterisk PBX 1.8.0-beta2 c=IN IP4 10.21.0.146 t=0 0 m=audio 13894 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5049 [Aug 9 14:19:40] DEBUG[4418] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.13.22.38:5060 [Aug 9 14:19:40] VERBOSE[4418] app_dial.c: -- Called 6000 [Aug 9 14:19:40] DEBUG[4418] channel.c: Set channel SIP/6000-00000057 to read format slin [Aug 9 14:19:40] DEBUG[4418] channel.c: Set channel SIP/4709-00000056 to write format slin [Aug 9 14:19:40] DEBUG[4418] channel.c: Set channel SIP/4709-00000056 to read format slin [Aug 9 14:19:40] DEBUG[4418] channel.c: Set channel SIP/6000-00000057 to write format slin [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:40] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:41] VERBOSE[31464] chan_sip.c: <--- SIP read from UDP:10.13.22.38:5060 ---> SIP/2.0 182 Queued From: "Polycom";tag=as3d001dbc To: ;tag=87ae10-26160d0a-13c4-50029-386eb6ab-44a52c97-386eb6ab Call-ID: 02f603a20277b5503604fba839fa3fd3@10.21.0.146:5061 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK74b70e26 Supported: replaces,100rel User-Agent: AUDC-IPPhone/1.2.1_build_6 (320HD;00908F1ED22E) Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE Contact: Content-Length: 0 <-------------> [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 0 [ 18]: SIP/2.0 182 Queued [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 1 [ 57]: From: "Polycom";tag=as3d001dbc [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 2 [ 89]: To: ;tag=87ae10-26160d0a-13c4-50029-386eb6ab-44a52c97-386eb6ab [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 3 [ 58]: Call-ID: 02f603a20277b5503604fba839fa3fd3@10.21.0.146:5061 [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 5 [ 56]: Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK74b70e26 [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 6 [ 26]: Supported: replaces,100rel [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 7 [ 59]: User-Agent: AUDC-IPPhone/1.2.1_build_6 (320HD;00908F1ED22E) [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 8 [ 89]: Allow: REGISTER, INVITE, ACK, BYE, REFER, NOTIFY, CANCEL, INFO, OPTIONS, PRACK, SUBSCRIBE [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 9 [ 36]: Contact: [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Header 11 [ 0]: [Aug 9 14:19:41] VERBOSE[31464] chan_sip.c: --- (11 headers 0 lines) --- [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: *** SIP TIMER: Cancelling retransmission #5049 - INVITE (got response) [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '02f603a20277b5503604fba839fa3fd3@10.21.0.146:5061' Request 102: Found [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: SIP response 182 to standard invite [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:41] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:41] VERBOSE[4418] app_dial.c: -- SIP/6000-00000057 is ringing [Aug 9 14:19:41] DEBUG[4418] rtp_engine.c: Setting early bridge SDP of 'SIP/4709-00000056' with that of 'SIP/6000-00000057' [Aug 9 14:19:41] VERBOSE[4418] chan_sip.c: <--- Transmitting (no NAT) to 10.13.22.63:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.13.22.63;branch=z9hG4bK95c8825fAB8B4FC4;received=10.13.22.63 From: "4709" ;tag=54B65261-741E19AE To: ;tag=as3e20cf22 Call-ID: 631c0e72-5cfe31f3-d0c98868@10.13.22.63 CSeq: 2 INVITE Server: Asterisk PBX 1.8.0-beta2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [Aug 9 14:19:41] DEBUG[4418] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.13.22.63:5060 [Aug 9 14:19:41] DEBUG[31458] devicestate.c: No provider found, checking channel drivers for SIP - 6000 [Aug 9 14:19:41] DEBUG[31458] chan_sip.c: Checking device state for peer 6000 [Aug 9 14:19:41] DEBUG[31458] devicestate.c: Changing state for SIP/6000 - state 7 (Ring+Inuse) [Aug 9 14:19:41] DEBUG[31458] devicestate.c: device 'SIP/6000' state '7' [Aug 9 14:19:42] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:42] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Session timer expired: 5035 - 8249824951312000205123@10.21.0.135 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Strict routing enforced for session 8249824951312000205123@10.21.0.135 [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: set_destination: Parsing for address/port to send to [Aug 9 14:19:43] DEBUG[31464] netsock2.c: Splitting '10.21.0.135:5060' gives... [Aug 9 14:19:43] DEBUG[31464] netsock2.c: ...host '10.21.0.135' and port '5060'. [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: set_destination: set destination to 10.21.0.135:5060 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: Audio is at 5061 [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: -- Done with adding codecs to SDP [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Initializing already initialized SIP dialog 8249824951312000205123@10.21.0.135 (presumably reinvite) [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 0 [ 43]: INVITE sip:9764701@10.21.0.135:5060 SIP/2.0 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK6b654fcb [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 3 [ 43]: From: ;tag=as0d5c0072 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 4 [ 55]: To: "9764701" ;tag=1c824983360 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 5 [ 36]: Contact: [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 6 [ 43]: Call-ID: 8249824951312000205123@10.21.0.135 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 7 [ 16]: CSeq: 103 INVITE [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 8 [ 36]: User-Agent: Asterisk PBX 1.8.0-beta2 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 9 [ 14]: Require: timer [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 10 [ 34]: Session-Expires: 150;refresher=uas [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 11 [ 10]: Min-SE: 90 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 12 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 13 [ 26]: Supported: replaces, timer [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 14 [ 47]: X-asterisk-Info: SIP re-invite (Session-Timers) [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 15 [ 29]: Content-Type: application/sdp [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: Reliably Transmitting (no NAT) to 10.21.0.135:5060: INVITE sip:9764701@10.21.0.135:5060 SIP/2.0 Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK6b654fcb Max-Forwards: 70 From: ;tag=as0d5c0072 To: "9764701" ;tag=1c824983360 Contact: Call-ID: 8249824951312000205123@10.21.0.135 CSeq: 103 INVITE User-Agent: Asterisk PBX 1.8.0-beta2 Require: timer Session-Expires: 150;refresher=uas Min-SE: 90 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer X-asterisk-Info: SIP re-invite (Session-Timers) Content-Type: application/sdp Content-Length: 264 v=0 o=root 1715362474 1715362475 IN IP4 10.13.22.38 s=Asterisk PBX 1.8.0-beta2 c=IN IP4 10.13.22.38 t=0 0 m=audio 4000 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5052 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.21.0.135:5060 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: <--- SIP read from UDP:10.21.0.135:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK6b654fcb From: ;tag=as0d5c0072 To: "9764701" ;tag=1c824983360 Call-ID: 8249824951312000205123@10.21.0.135 CSeq: 103 INVITE Contact: Supported: em,replaces,path,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Require: timer Session-Expires: 150;refresher=uas Min-SE: 90 Server: Audiocodes-Sip-Gateway-/v.5.80A.023.006 Content-Type: application/sdp Content-Length: 251 v=0 o=AudiocodesGW 824972953 824972649 IN IP4 10.21.0.135 s=Phone-Call c=IN IP4 10.21.0.135 t=0 0 m=audio 7800 RTP/AVP 8 101 c=IN IP4 10.21.0.135 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK6b654fcb [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 2 [ 43]: From: ;tag=as0d5c0072 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 3 [ 55]: To: "9764701" ;tag=1c824983360 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 4 [ 43]: Call-ID: 8249824951312000205123@10.21.0.135 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 5 [ 16]: CSeq: 103 INVITE [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 6 [ 39]: Contact: [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 7 [ 45]: Supported: em,replaces,path,resource-priority [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 8 [ 86]: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 9 [ 14]: Require: timer [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 10 [ 34]: Session-Expires: 150;refresher=uas [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 11 [ 10]: Min-SE: 90 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 12 [ 47]: Server: Audiocodes-Sip-Gateway-/v.5.80A.023.006 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 14 [ 19]: Content-Length: 251 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Header 15 [ 0]: [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 0 [ 3]: v=0 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 1 [ 53]: o=AudiocodesGW 824972953 824972649 IN IP4 10.21.0.135 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 2 [ 12]: s=Phone-Call [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.21.0.135 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 4 [ 5]: t=0 0 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 5 [ 26]: m=audio 7800 RTP/AVP 8 101 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 6 [ 20]: c=IN IP4 10.21.0.135 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-15 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Body 11 [ 10]: a=sendrecv [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: --- (15 headers 12 lines) --- [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Acked pending invite 103 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5052 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Stopping retransmission on '8249824951312000205123@10.21.0.135' of Request 103: Match Found [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: SIP response 200 to RE-invite on outgoing call 8249824951312000205123@10.21.0.135 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Call 8249824951312000205123@10.21.0.135 responded to our reinvite without changing SDP version; ignoring SDP. [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Updating call counter for incoming call [Aug 9 14:19:43] DEBUG[31458] devicestate.c: No provider found, checking channel drivers for SIP - M1k_Shay [Aug 9 14:19:43] DEBUG[31458] chan_sip.c: Checking device state for peer M1k_Shay [Aug 9 14:19:43] DEBUG[31458] devicestate.c: Changing state for SIP/M1k_Shay - state 1 (Not in use) [Aug 9 14:19:43] DEBUG[31458] devicestate.c: device 'SIP/M1k_Shay' state '1' [Aug 9 14:19:43] DEBUG[31464] netsock2.c: Splitting '10.21.0.135:5060' gives... [Aug 9 14:19:43] DEBUG[31464] netsock2.c: ...host '10.21.0.135' and port '5060'. [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Strict routing enforced for session 8249824951312000205123@10.21.0.135 [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: set_destination: Parsing for address/port to send to [Aug 9 14:19:43] DEBUG[31464] netsock2.c: Splitting '10.21.0.135:5060' gives... [Aug 9 14:19:43] DEBUG[31464] netsock2.c: ...host '10.21.0.135' and port '5060'. [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: set_destination: set destination to 10.21.0.135:5060 [Aug 9 14:19:43] VERBOSE[31464] chan_sip.c: Transmitting (no NAT) to 10.21.0.135:5060: ACK sip:9764701@10.21.0.135:5060 SIP/2.0 Via: SIP/2.0/UDP 10.21.0.146:5061;branch=z9hG4bK5696f83b Max-Forwards: 70 From: ;tag=as0d5c0072 To: "9764701" ;tag=1c824983360 Contact: Call-ID: 8249824951312000205123@10.21.0.135 CSeq: 103 ACK User-Agent: Asterisk PBX 1.8.0-beta2 Content-Length: 0 --- [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Trying to put 'ACK sip:976' onto UDP socket destined for 10.21.0.135:5060 [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:43] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:44] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:44] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:45] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:45] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:46] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:46] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:47] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:47] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:48] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:48] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:49] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:49] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:19:50] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '13faca181d5edf0b302f931124d642e4@10.21.0.146:5061' Method: INVITE [Aug 9 14:19:50] DEBUG[31464] chan_sip.c: Bridge still active. Delaying destroy of SIP dialog '8249824951312000205123@10.21.0.135' Method: ACK [Aug 9 14:20:00] WARNING[4418] channel.c: No path to translate from SIP/5000000-00000058 to SIP/4709-00000056 [Aug 9 14:20:01] WARNING[4418] channel.c: Unable to find a codec translation path from 0x8 (alaw) to 0x100 (g729) [Aug 9 14:20:01] WARNING[4418] channel.c: Unable to find a codec translation path from 0x8 (alaw) to 0x100 (g729) [Aug 9 14:20:01] VERBOSE[4418] rtp_engine.c: -- Remotely bridging SIP/4709-00000056 and SIP/5000000-00000058