[May 10 18:25:17] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1071 ---> INVITE sip:111@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK3d8b5cd7 From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 Date: Thu, 10 May 2007 22:25:16 GMT CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Expires: 180 Content-Type: application/sdp Content-Length: 247 Accept: application/sdp v=0 o=Cisco-SIPUA 9034 6623 IN IP4 192.168.0.217 s=SIP Call c=IN IP4 192.168.0.217 t=0 0 m=audio 29672 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 0: INVITE sip:111@66.114.80.26 SIP/2.0 (35) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK3d8b5cd7 (58) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 (91) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 3: To: (26) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 4: Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 (58) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 5: Date: Thu, 10 May 2007 22:25:16 GMT (35) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 6: CSeq: 101 INVITE (16) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 8: Contact: (51) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 9: Expires: 180 (12) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 10: Content-Type: application/sdp (29) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 11: Content-Length: 247 (19) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 12: Accept: application/sdp (23) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 13: (0) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: o=Cisco-SIPUA 9034 6623 IN IP4 192.168.0.217 (44) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: s=SIP Call (10) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.217 (22) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: m=audio 29672 RTP/AVP 0 8 18 101 (32) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=fmtp:101 0-15 (15) [May 10 18:25:17] VERBOSE[25684] logger.c: --- (13 headers 11 lines) --- [May 10 18:25:17] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:17] DEBUG[25684] chan_sip.c: Allocating new SIP dialog for 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 - INVITE (With RTP) [May 10 18:25:17] DEBUG[25684] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 10 18:25:17] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1071 (NAT) [May 10 18:25:17] VERBOSE[25684] logger.c: Using INVITE request as basis request - 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 [May 10 18:25:17] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:17] VERBOSE[25684] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1071 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK3d8b5cd7;received=66.114.80.25 From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: ;tag=as05a7efb8 Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 CSeq: 101 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="acepbx.com", nonce="72a068a0" Content-Length: 0 <------------> [May 10 18:25:17] DEBUG[25684] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #320 [May 10 18:25:17] VERBOSE[25684] logger.c: Scheduling destruction of SIP dialog '003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217' in 32000 ms (Method: INVITE) [May 10 18:25:17] VERBOSE[25684] logger.c: Found user '12128121207010001' [May 10 18:25:17] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1071 ---> ACK sip:111@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK3d8b5cd7 From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: ;tag=as05a7efb8 Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 Date: Thu, 10 May 2007 22:25:16 GMT CSeq: 101 ACK Content-Length: 0 <-------------> [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 0: ACK sip:111@66.114.80.26 SIP/2.0 (32) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK3d8b5cd7 (58) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 (91) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=as05a7efb8 (41) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 4: Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 (58) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 5: Date: Thu, 10 May 2007 22:25:16 GMT (35) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 6: CSeq: 101 ACK (13) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 7: Content-Length: 0 (17) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 8: (0) [May 10 18:25:17] VERBOSE[25684] logger.c: --- (8 headers 0 lines) --- [May 10 18:25:17] DEBUG[25684] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 10 18:25:17] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #320 [May 10 18:25:17] DEBUG[25684] chan_sip.c: Stopping retransmission on '003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217' of Response 101: Match Not Found [May 10 18:25:17] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1071 ---> INVITE sip:111@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK4b6981f5 From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 Date: Thu, 10 May 2007 22:25:16 GMT CSeq: 102 INVITE User-Agent: CSCO/7 Contact: Proxy-Authorization: Digest username="12128121207010001",realm="acepbx.com",uri="sip:66.114.80.26",response="9d813183c39089495bd52d5915d0256d",nonce="72a068a0",algorithm=MD5 Expires: 180 Content-Type: application/sdp Content-Length: 247 v=0 o=Cisco-SIPUA 9034 6623 IN IP4 192.168.0.217 s=SIP Call c=IN IP4 192.168.0.217 t=0 0 m=audio 29672 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 0: INVITE sip:111@66.114.80.26 SIP/2.0 (35) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK4b6981f5 (58) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 (91) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 3: To: (26) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 4: Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 (58) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 5: Date: Thu, 10 May 2007 22:25:16 GMT (35) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 8: Contact: (51) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 9: Proxy-Authorization: Digest username="12128121207010001",realm="acepbx.com",uri="sip:66.114.80.26",response="9d813183c39089495bd52d5915d0256d",nonce="72a068a0",algorithm=MD5 (173) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 10: Expires: 180 (12) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 11: Content-Type: application/sdp (29) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 12: Content-Length: 247 (19) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Header 13: (0) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: o=Cisco-SIPUA 9034 6623 IN IP4 192.168.0.217 (44) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: s=SIP Call (10) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.217 (22) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: m=audio 29672 RTP/AVP 0 8 18 101 (32) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Line: a=fmtp:101 0-15 (15) [May 10 18:25:17] VERBOSE[25684] logger.c: --- (13 headers 11 lines) --- [May 10 18:25:17] DEBUG[25684] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 10 18:25:17] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1071 (NAT) [May 10 18:25:17] VERBOSE[25684] logger.c: Using INVITE request as basis request - 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 [May 10 18:25:17] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:17] VERBOSE[25684] logger.c: Found user '12128121207010001' [May 10 18:25:17] VERBOSE[25684] logger.c: Found RTP audio format 0 [May 10 18:25:17] VERBOSE[25684] logger.c: Found RTP audio format 8 [May 10 18:25:17] VERBOSE[25684] logger.c: Found RTP audio format 18 [May 10 18:25:17] VERBOSE[25684] logger.c: Found RTP audio format 101 [May 10 18:25:17] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.217:29672 [May 10 18:25:17] VERBOSE[25684] logger.c: Found description format PCMU for ID 0 [May 10 18:25:17] VERBOSE[25684] logger.c: Found description format PCMA for ID 8 [May 10 18:25:17] VERBOSE[25684] logger.c: Found description format G729 for ID 18 [May 10 18:25:17] VERBOSE[25684] logger.c: Found description format telephone-event for ID 101 [May 10 18:25:17] VERBOSE[25684] logger.c: Got unsupported a:fmtp in SDP offer [May 10 18:25:17] DEBUG[25684] chan_sip.c: T38 state changed to 0 on channel [May 10 18:25:17] VERBOSE[25684] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [May 10 18:25:17] VERBOSE[25684] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 10 18:25:17] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.217:29672 [May 10 18:25:17] DEBUG[25684] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [May 10 18:25:17] DEBUG[25684] chan_sip.c: Checking SIP call limits for device 12128121207010001 [May 10 18:25:17] DEBUG[25684] chan_sip.c: Updating call counter for incoming call [May 10 18:25:17] DEBUG[25684] chan_sip.c: Call from peer '12128121207010001' is 1 out of 3 [May 10 18:25:17] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001 [May 10 18:25:17] VERBOSE[25684] logger.c: Looking for 111 in xyz (domain 66.114.80.26) [May 10 18:25:17] DEBUG[25684] chan_sip.c: *** Our native formats are 0x4 (ulaw) [May 10 18:25:17] DEBUG[25684] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [May 10 18:25:17] DEBUG[25684] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [May 10 18:25:17] DEBUG[25684] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 10 18:25:17] DEBUG[25684] chan_sip.c: This channel will not be able to handle video. [May 10 18:25:17] DEBUG[25684] chan_sip.c: build_route: Contact hop: [May 10 18:25:17] VERBOSE[25684] logger.c: list_route: hop: [May 10 18:25:18] DEBUG[25684] chan_sip.c: SIP/12128121207010001-081dd788: New call is still down.... Trying... [May 10 18:25:18] VERBOSE[25684] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1071 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK4b6981f5;received=66.114.80.25 From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 CSeq: 102 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 10 18:25:18] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081dd788 [May 10 18:25:17] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [May 10 18:25:18] DEBUG[25674] chan_sip.c: Checking device state for peer 12128121207010001 [May 10 18:25:18] DEBUG[25674] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [May 10 18:25:18] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [May 10 18:25:18] DEBUG[25674] chan_sip.c: Checking device state for peer 12128121207010001 [May 10 18:25:18] DEBUG[25674] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [May 10 18:25:18] DEBUG[25717] pbx.c: Launching 'Set' [May 10 18:25:18] VERBOSE[25717] logger.c: -- Executing [111@xyz:1] Set("SIP/12128121207010001-081dd788", "TIMEOUT(absolute)=10800") in new stack [May 10 18:25:18] VERBOSE[25717] logger.c: -- Channel will hangup at 2007-05-11 01:25:18 UTC. [May 10 18:25:18] DEBUG[25717] pbx.c: Launching 'AGI' [May 10 18:25:18] VERBOSE[25717] logger.c: -- Executing [111@xyz:2] AGI("SIP/12128121207010001-081dd788", "callprocessing.agi") in new stack [May 10 18:25:18] VERBOSE[25717] logger.c: -- Launched AGI Script /usr/local/asterisk/var/lib/asterisk/agi-bin/callprocessing.agi [May 10 18:25:18] DEBUG[25717] pbx.c: Function result is '12128121207010001' [May 10 18:25:19] VERBOSE[25717] logger.c: -- AGI Script Executing Application: (SetCallerPres) Options: (allowed_passed_screen) [May 10 18:25:19] VERBOSE[25717] logger.c: -- AGI Script Executing Application: (Set) Options: (CALLERID(name)=xyz main|CALLERID(num)=100) [May 10 18:25:19] VERBOSE[25717] logger.c: -- AGI Script Executing Application: (Dial) Options: (SIP/xyz011101|15|) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:19] DEBUG[25717] chan_sip.c: *** Our native formats are 0x4 (ulaw) [May 10 18:25:19] DEBUG[25717] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [May 10 18:25:19] DEBUG[25717] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [May 10 18:25:19] DEBUG[25717] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 10 18:25:19] DEBUG[25717] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [May 10 18:25:19] DEBUG[25717] chan_sip.c: This channel will not be able to handle video. [May 10 18:25:19] DEBUG[25717] channel.c: Not copying variable CP_PID. [May 10 18:25:19] DEBUG[25717] channel.c: Not copying variable STACK-xyz-111-2. [May 10 18:25:19] DEBUG[25717] channel.c: Not copying variable STACK-xyz-111-1. [May 10 18:25:19] DEBUG[25717] channel.c: Not copying variable SIPCALLID. [May 10 18:25:19] DEBUG[25717] channel.c: Not copying variable SIPUSERAGENT. [May 10 18:25:19] DEBUG[25717] channel.c: Not copying variable SIPDOMAIN. [May 10 18:25:19] DEBUG[25717] channel.c: Not copying variable SIPURI. [May 10 18:25:19] DEBUG[25717] chan_sip.c: Outgoing Call for xyz011101 [May 10 18:25:19] DEBUG[25717] chan_sip.c: Updating call counter for outgoing call [May 10 18:25:19] DEBUG[25717] chan_sip.c: Call to peer 'xyz011101' is 1 out of 3 [May 10 18:25:19] DEBUG[25717] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101 [May 10 18:25:19] DEBUG[25717] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [May 10 18:25:19] DEBUG[25717] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [May 10 18:25:19] DEBUG[25717] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [May 10 18:25:19] VERBOSE[25717] logger.c: Audio is at 66.114.80.26 port 46284 [May 10 18:25:19] VERBOSE[25717] logger.c: Adding codec 0x4 (ulaw) to SDP [May 10 18:25:19] VERBOSE[25717] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [May 10 18:25:19] DEBUG[25717] chan_sip.c: -- Done with adding codecs to SDP [May 10 18:25:19] DEBUG[25717] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 0: INVITE sip:xyz011101@192.168.0.250 SIP/2.0 (42) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport (63) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 2: From: "xyz main" ;tag=as79e36426 (54) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 3: To: (33) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 4: Contact: (31) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 7: User-Agent: AcePBX (18) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 9: Date: Thu, 10 May 2007 22:25:19 GMT (35) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 11: Supported: replaces (19) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 13: Content-Length: 213 (19) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Header 14: (0) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: v=0 (3) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: o=root 25553 25553 IN IP4 66.114.80.26 (38) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: s=session (9) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: c=IN IP4 66.114.80.26 (21) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: m=audio 46284 RTP/AVP 0 101 (27) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: a=fmtp:101 0-16 (15) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: a=ptime:20 (10) [May 10 18:25:19] DEBUG[25717] chan_sip.c: Line: a=sendrecv (10) [May 10 18:25:19] VERBOSE[25717] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1109: INVITE sip:xyz011101@192.168.0.250 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport From: "xyz main" ;tag=as79e36426 To: Contact: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 CSeq: 102 INVITE User-Agent: AcePBX Max-Forwards: 70 Date: Thu, 10 May 2007 22:25:19 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 213 v=0 o=root 25553 25553 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 46284 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [May 10 18:25:19] DEBUG[25717] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #322 [May 10 18:25:19] VERBOSE[25717] logger.c: -- Called xyz011101 [May 10 18:25:19] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:19] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:19] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 6 (Ringing) [May 10 18:25:19] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport From: "xyz main" ;tag=as79e36426 To: ;tag=3586B7C0-BD2DEC51 CSeq: 102 INVITE Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Content-Length: 0 <-------------> [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport (63) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=as79e36426 (54) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=3586B7C0-BD2DEC51 (55) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 4: CSeq: 102 INVITE (16) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 8: Content-Length: 0 (17) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 9: (0) [May 10 18:25:19] VERBOSE[25684] logger.c: --- (9 headers 0 lines) --- [May 10 18:25:19] DEBUG[25684] chan_sip.c: *** SIP TIMER: Cancelling retransmission #322 - INVITE (got response) [May 10 18:25:19] DEBUG[25684] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '23816a2d3fde880f560b05385a64b744@66.114.80.26' Request 102: Found [May 10 18:25:19] DEBUG[25684] chan_sip.c: SIP response 100 to standard invite [May 10 18:25:19] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport From: "xyz main" ;tag=as79e36426 To: ;tag=3586B7C0-BD2DEC51 CSeq: 102 INVITE Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Allow-Events: talk,hold,conference Content-Length: 0 <-------------> [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport (63) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=as79e36426 (54) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=3586B7C0-BD2DEC51 (55) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 4: CSeq: 102 INVITE (16) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 8: Allow-Events: talk,hold,conference (34) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 9: Content-Length: 0 (17) [May 10 18:25:19] DEBUG[25684] chan_sip.c: Header 10: (0) [May 10 18:25:19] VERBOSE[25684] logger.c: --- (10 headers 0 lines) --- [May 10 18:25:19] DEBUG[25684] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '23816a2d3fde880f560b05385a64b744@66.114.80.26' Request 102: Found [May 10 18:25:19] DEBUG[25684] chan_sip.c: SIP response 180 to standard invite [May 10 18:25:19] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081e3d18 [May 10 18:25:19] VERBOSE[25717] logger.c: -- SIP/xyz011101-081e3d18 is ringing [May 10 18:25:19] VERBOSE[25717] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1071 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK4b6981f5;received=66.114.80.25 From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: ;tag=as68907c14 Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 CSeq: 102 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 10 18:25:19] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:19] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:19] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 6 (Ringing) [May 10 18:25:21] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport From: "xyz main" ;tag=as79e36426 To: ;tag=3586B7C0-BD2DEC51 CSeq: 102 INVITE Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Content-Type: application/sdp Content-Length: 201 v=0 o=- 1178813044 1178813044 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 m=audio 2234 RTP/AVP 0 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 <-------------> [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK23db59cf;rport (63) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=as79e36426 (54) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=3586B7C0-BD2DEC51 (55) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 4: CSeq: 102 INVITE (16) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 9: Content-Type: application/sdp (29) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 10: Content-Length: 201 (19) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 11: (0) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: o=- 1178813044 1178813044 IN IP4 192.168.0.250 (46) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: s=Polycom IP Phone (18) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: m=audio 2234 RTP/AVP 0 101 (26) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: a=sendrecv (10) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:21] VERBOSE[25684] logger.c: --- (11 headers 9 lines) --- [May 10 18:25:21] DEBUG[25684] chan_sip.c: Acked pending invite 102 [May 10 18:25:21] DEBUG[25684] chan_sip.c: Stopping retransmission on '23816a2d3fde880f560b05385a64b744@66.114.80.26' of Request 102: Match Not Found [May 10 18:25:21] DEBUG[25684] chan_sip.c: SIP response 200 to standard invite [May 10 18:25:21] VERBOSE[25684] logger.c: Found RTP audio format 0 [May 10 18:25:21] VERBOSE[25684] logger.c: Found RTP audio format 101 [May 10 18:25:21] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2234 [May 10 18:25:21] VERBOSE[25684] logger.c: Found description format PCMU for ID 0 [May 10 18:25:21] VERBOSE[25684] logger.c: Found description format telephone-event for ID 101 [May 10 18:25:21] DEBUG[25684] chan_sip.c: T38 state changed to 0 on channel SIP/xyz011101-081e3d18 [May 10 18:25:21] VERBOSE[25684] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [May 10 18:25:21] VERBOSE[25684] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 10 18:25:21] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2234 [May 10 18:25:21] DEBUG[25684] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [May 10 18:25:21] DEBUG[25684] chan_sip.c: We have an owner, now see if we need to change this call [May 10 18:25:21] DEBUG[25684] chan_sip.c: Updating call counter for outgoing call [May 10 18:25:21] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101 [May 10 18:25:21] DEBUG[25684] chan_sip.c: build_route: Contact hop: [May 10 18:25:21] VERBOSE[25684] logger.c: list_route: hop: [May 10 18:25:21] DEBUG[25684] chan_sip.c: Strict routing enforced for session 23816a2d3fde880f560b05385a64b744@66.114.80.26 [May 10 18:25:21] VERBOSE[25684] logger.c: set_destination: Parsing for address/port to send to [May 10 18:25:21] VERBOSE[25684] logger.c: set_destination: set destination to 192.168.0.250, port 5060 [May 10 18:25:21] VERBOSE[25684] logger.c: Transmitting (NAT) to 66.114.80.25:1109: ACK sip:xyz011101@192.168.0.250 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK38a5d5fd;rport From: "xyz main" ;tag=as79e36426 To: ;tag=3586B7C0-BD2DEC51 Contact: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 CSeq: 102 ACK User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [May 10 18:25:21] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:21] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:21] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:21] DEBUG[25717] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081e3d18 [May 10 18:25:21] VERBOSE[25717] logger.c: -- SIP/xyz011101-081e3d18 answered SIP/12128121207010001-081dd788 [May 10 18:25:21] DEBUG[25717] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081dd788 [May 10 18:25:21] DEBUG[25717] chan_sip.c: SIP answering channel: SIP/12128121207010001-081dd788 [May 10 18:25:21] DEBUG[25717] chan_sip.c: Setting framing from config on incoming call [May 10 18:25:21] DEBUG[25717] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [May 10 18:25:21] DEBUG[25717] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [May 10 18:25:21] VERBOSE[25717] logger.c: Audio is at 66.114.80.26 port 42744 [May 10 18:25:21] VERBOSE[25717] logger.c: Adding codec 0x4 (ulaw) to SDP [May 10 18:25:21] VERBOSE[25717] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [May 10 18:25:21] DEBUG[25717] chan_sip.c: -- Done with adding codecs to SDP [May 10 18:25:21] DEBUG[25717] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [May 10 18:25:21] VERBOSE[25717] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1071 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK4b6981f5;received=66.114.80.25 From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: ;tag=as68907c14 Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 CSeq: 102 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 213 v=0 o=root 25553 25553 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 42744 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [May 10 18:25:21] DEBUG[25717] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #324 [May 10 18:25:21] VERBOSE[25717] logger.c: -- Packet2Packet bridging SIP/12128121207010001-081dd788 and SIP/xyz011101-081e3d18 [May 10 18:25:21] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:21] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:21] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:21] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [May 10 18:25:21] DEBUG[25674] chan_sip.c: Checking device state for peer 12128121207010001 [May 10 18:25:21] DEBUG[25674] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [May 10 18:25:21] DEBUG[25717] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2234 [May 10 18:25:21] DEBUG[25717] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:29672 [May 10 18:25:21] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1071 ---> ACK sip:111@66.114.80.26:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK2f6a4c6e From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 To: ;tag=as68907c14 Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 Date: Thu, 10 May 2007 22:25:20 GMT CSeq: 102 ACK User-Agent: CSCO/7 Proxy-Authorization: Digest username="12128121207010001",realm="acepbx.com",uri="sip:66.114.80.26",response="9d813183c39089495bd52d5915d0256d",nonce="72a068a0",algorithm=MD5 Content-Length: 0 <-------------> [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 0: ACK sip:111@66.114.80.26:5060 SIP/2.0 (37) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK2f6a4c6e (58) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=003094c44b8900084d9e89aa-0d3a3f26 (91) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=as68907c14 (41) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 4: Call-ID: 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217 (58) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 5: Date: Thu, 10 May 2007 22:25:20 GMT (35) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 6: CSeq: 102 ACK (13) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 8: Proxy-Authorization: Digest username="12128121207010001",realm="acepbx.com",uri="sip:66.114.80.26",response="9d813183c39089495bd52d5915d0256d",nonce="72a068a0",algorithm=MD5 (173) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 9: Content-Length: 0 (17) [May 10 18:25:21] DEBUG[25684] chan_sip.c: Header 10: (0) [May 10 18:25:21] VERBOSE[25684] logger.c: --- (10 headers 0 lines) --- [May 10 18:25:21] DEBUG[25684] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 10 18:25:21] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #324 [May 10 18:25:21] DEBUG[25684] chan_sip.c: Stopping retransmission on '003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217' of Response 102: Match Not Found [May 10 18:25:22] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> INVITE sip:100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKaf9dd5b583E2E834 From: ;tag=3586B7C0-BD2DEC51 To: "xyz main" ;tag=as79e36426 CSeq: 1 INVITE Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 201 v=0 o=- 1178813044 1178813045 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 m=audio 2234 RTP/AVP 0 101 a=sendonly a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 <-------------> [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 0: INVITE sip:100@66.114.80.26 SIP/2.0 (35) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKaf9dd5b583E2E834 (61) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 2: From: ;tag=3586B7C0-BD2DEC51 (57) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 3: To: "xyz main" ;tag=as79e36426 (52) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 4: CSeq: 1 INVITE (14) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 11: Max-Forwards: 70 (16) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 13: Content-Length: 201 (19) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 14: (0) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: o=- 1178813044 1178813045 IN IP4 192.168.0.250 (46) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: s=Polycom IP Phone (18) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: m=audio 2234 RTP/AVP 0 101 (26) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: a=sendonly (10) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:22] VERBOSE[25684] logger.c: --- (14 headers 9 lines) --- [May 10 18:25:22] DEBUG[25684] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 10 18:25:22] DEBUG[25684] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [May 10 18:25:22] DEBUG[25684] chan_sip.c: Found SIP option: -100rel- [May 10 18:25:22] DEBUG[25684] chan_sip.c: Matched SIP option: 100rel [May 10 18:25:22] DEBUG[25684] chan_sip.c: Found SIP option: -replaces- [May 10 18:25:22] DEBUG[25684] chan_sip.c: Matched SIP option: replaces [May 10 18:25:22] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1109 (NAT) [May 10 18:25:22] VERBOSE[25684] logger.c: Found RTP audio format 0 [May 10 18:25:22] VERBOSE[25684] logger.c: Found RTP audio format 101 [May 10 18:25:22] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2234 [May 10 18:25:22] VERBOSE[25684] logger.c: Found description format PCMU for ID 0 [May 10 18:25:22] VERBOSE[25684] logger.c: Found description format telephone-event for ID 101 [May 10 18:25:22] DEBUG[25684] chan_sip.c: T38 state changed to 0 on channel SIP/xyz011101-081e3d18 [May 10 18:25:22] VERBOSE[25684] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [May 10 18:25:22] VERBOSE[25684] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 10 18:25:22] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2234 [May 10 18:25:22] DEBUG[25684] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [May 10 18:25:22] DEBUG[25684] chan_sip.c: We have an owner, now see if we need to change this call [May 10 18:25:22] DEBUG[25684] chan_sip.c: Got a SIP re-invite for call 23816a2d3fde880f560b05385a64b744@66.114.80.26 [May 10 18:25:22] DEBUG[25684] chan_sip.c: SIP/xyz011101-081e3d18: This call is UP.... [May 10 18:25:22] DEBUG[25684] chan_sip.c: Setting framing from config on incoming call [May 10 18:25:22] DEBUG[25684] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [May 10 18:25:22] DEBUG[25684] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [May 10 18:25:22] VERBOSE[25684] logger.c: Audio is at 66.114.80.26 port 46284 [May 10 18:25:22] VERBOSE[25684] logger.c: Adding codec 0x4 (ulaw) to SDP [May 10 18:25:22] VERBOSE[25684] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [May 10 18:25:22] DEBUG[25684] chan_sip.c: -- Done with adding codecs to SDP [May 10 18:25:22] DEBUG[25684] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [May 10 18:25:22] VERBOSE[25684] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKaf9dd5b583E2E834;received=66.114.80.25 From: ;tag=3586B7C0-BD2DEC51 To: "xyz main" ;tag=as79e36426 Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 CSeq: 1 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 213 v=0 o=root 25553 25554 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 46284 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=recvonly <------------> [May 10 18:25:22] DEBUG[25684] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #325 [May 10 18:25:22] DEBUG[25717] rtp.c: RTP Transmission error of packet to 0.0.0.0:0: Invalid argument [May 10 18:25:22] DEBUG[25717] channel.c: Set channel SIP/12128121207010001-081dd788 to write format slin [May 10 18:25:22] VERBOSE[25717] logger.c: -- Started music on hold, class 'xyz', on channel 'SIP/12128121207010001-081dd788' [May 10 18:25:22] DEBUG[25717] channel.c: Scheduling timer at 160 sample intervals [May 10 18:25:22] DEBUG[25717] rtp.c: Ooh, format changed from unknown to ulaw [May 10 18:25:22] DEBUG[25717] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [May 10 18:25:22] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> ACK sip:100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK4d90154fAB96A5F6 From: ;tag=3586B7C0-BD2DEC51 To: "xyz main" ;tag=as79e36426 CSeq: 1 ACK Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 0: ACK sip:100@66.114.80.26 SIP/2.0 (32) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK4d90154fAB96A5F6 (61) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 2: From: ;tag=3586B7C0-BD2DEC51 (57) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 3: To: "xyz main" ;tag=as79e36426 (52) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 4: CSeq: 1 ACK (11) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 9: Max-Forwards: 70 (16) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 10: Content-Length: 0 (17) [May 10 18:25:22] DEBUG[25684] chan_sip.c: Header 11: (0) [May 10 18:25:22] VERBOSE[25684] logger.c: --- (11 headers 0 lines) --- [May 10 18:25:22] DEBUG[25684] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 10 18:25:22] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #325 [May 10 18:25:22] DEBUG[25684] chan_sip.c: Stopping retransmission on '23816a2d3fde880f560b05385a64b744@66.114.80.26' of Response 1: Match Not Found [May 10 18:25:24] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> INVITE sip:700@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK7e7570d94A8E7968 From: "poly work" ;tag=D7107017-7B3CDF5C To: CSeq: 1 INVITE Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1178813047 1178813047 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 m=audio 2236 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 0: INVITE sip:700@pbxtest.acecape.com:5060;user=phone SIP/2.0 (58) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK7e7570d94A8E7968 (61) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=D7107017-7B3CDF5C (75) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 3: To: (44) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 4: CSeq: 1 INVITE (14) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 (49) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 11: Max-Forwards: 70 (16) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 13: Content-Length: 251 (19) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 14: (0) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: o=- 1178813047 1178813047 IN IP4 192.168.0.250 (46) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: s=Polycom IP Phone (18) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: m=audio 2236 RTP/AVP 0 8 18 101 (31) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=sendrecv (10) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:24] VERBOSE[25684] logger.c: --- (14 headers 11 lines) --- [May 10 18:25:24] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:24] DEBUG[25684] chan_sip.c: Allocating new SIP dialog for 21afaad3-b06521bd-62299f0a@192.168.0.250 - INVITE (With RTP) [May 10 18:25:24] DEBUG[25684] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 10 18:25:24] DEBUG[25684] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [May 10 18:25:24] DEBUG[25684] chan_sip.c: Found SIP option: -100rel- [May 10 18:25:24] DEBUG[25684] chan_sip.c: Matched SIP option: 100rel [May 10 18:25:24] DEBUG[25684] chan_sip.c: Found SIP option: -replaces- [May 10 18:25:24] DEBUG[25684] chan_sip.c: Matched SIP option: replaces [May 10 18:25:24] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1109 (NAT) [May 10 18:25:24] VERBOSE[25684] logger.c: Using INVITE request as basis request - 21afaad3-b06521bd-62299f0a@192.168.0.250 [May 10 18:25:24] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:24] VERBOSE[25684] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK7e7570d94A8E7968;received=66.114.80.25 From: "poly work" ;tag=D7107017-7B3CDF5C To: ;tag=as31a81439 Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 CSeq: 1 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="acepbx.com", nonce="6bb9cd58" Content-Length: 0 <------------> [May 10 18:25:24] DEBUG[25684] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #327 [May 10 18:25:24] VERBOSE[25684] logger.c: Scheduling destruction of SIP dialog '21afaad3-b06521bd-62299f0a@192.168.0.250' in 32000 ms (Method: INVITE) [May 10 18:25:24] VERBOSE[25684] logger.c: Found user 'xyz011101' [May 10 18:25:24] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> ACK sip:700@pbxtest.acecape.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK7e7570d94A8E7968 From: "poly work" ;tag=D7107017-7B3CDF5C To: ;tag=as31a81439 CSeq: 1 ACK Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 0: ACK sip:700@pbxtest.acecape.com:5060 SIP/2.0 (44) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK7e7570d94A8E7968 (61) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=D7107017-7B3CDF5C (75) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=as31a81439 (59) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 4: CSeq: 1 ACK (11) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 (49) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 9: Max-Forwards: 70 (16) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 10: Content-Length: 0 (17) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 11: (0) [May 10 18:25:24] VERBOSE[25684] logger.c: --- (11 headers 0 lines) --- [May 10 18:25:24] DEBUG[25684] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 10 18:25:24] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #327 [May 10 18:25:24] DEBUG[25684] chan_sip.c: Stopping retransmission on '21afaad3-b06521bd-62299f0a@192.168.0.250' of Response 1: Match Not Found [May 10 18:25:24] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> INVITE sip:700@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK701caede755F0C61 From: "poly work" ;tag=D7107017-7B3CDF5C To: CSeq: 2 INVITE Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="6bb9cd58", uri="sip:700@pbxtest.acecape.com:5060;user=phone", response="9e4fb378084fa13f8fa83b34c9c403a1", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1178813047 1178813047 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 m=audio 2236 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 0: INVITE sip:700@pbxtest.acecape.com:5060;user=phone SIP/2.0 (58) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK701caede755F0C61 (61) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=D7107017-7B3CDF5C (75) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 3: To: (44) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 4: CSeq: 2 INVITE (14) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 (49) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="6bb9cd58", uri="sip:700@pbxtest.acecape.com:5060;user=phone", response="9e4fb378084fa13f8fa83b34c9c403a1", algorithm=MD5 (197) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 12: Max-Forwards: 70 (16) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 13: Content-Type: application/sdp (29) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 14: Content-Length: 251 (19) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 15: (0) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: o=- 1178813047 1178813047 IN IP4 192.168.0.250 (46) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: s=Polycom IP Phone (18) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: m=audio 2236 RTP/AVP 0 8 18 101 (31) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=sendrecv (10) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:24] VERBOSE[25684] logger.c: --- (15 headers 11 lines) --- [May 10 18:25:24] DEBUG[25684] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 10 18:25:24] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1109 (NAT) [May 10 18:25:24] VERBOSE[25684] logger.c: Using INVITE request as basis request - 21afaad3-b06521bd-62299f0a@192.168.0.250 [May 10 18:25:24] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:24] VERBOSE[25684] logger.c: Found user 'xyz011101' [May 10 18:25:24] VERBOSE[25684] logger.c: Found RTP audio format 0 [May 10 18:25:24] VERBOSE[25684] logger.c: Found RTP audio format 8 [May 10 18:25:24] VERBOSE[25684] logger.c: Found RTP audio format 18 [May 10 18:25:24] VERBOSE[25684] logger.c: Found RTP audio format 101 [May 10 18:25:24] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2236 [May 10 18:25:24] VERBOSE[25684] logger.c: Found description format PCMU for ID 0 [May 10 18:25:24] VERBOSE[25684] logger.c: Found description format PCMA for ID 8 [May 10 18:25:24] VERBOSE[25684] logger.c: Found description format G729 for ID 18 [May 10 18:25:24] VERBOSE[25684] logger.c: Found description format telephone-event for ID 101 [May 10 18:25:24] DEBUG[25684] chan_sip.c: T38 state changed to 0 on channel [May 10 18:25:24] VERBOSE[25684] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [May 10 18:25:24] VERBOSE[25684] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 10 18:25:24] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2236 [May 10 18:25:24] DEBUG[25684] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Checking SIP call limits for device xyz011101 [May 10 18:25:24] DEBUG[25684] chan_sip.c: Updating call counter for incoming call [May 10 18:25:24] DEBUG[25684] chan_sip.c: Call from peer 'xyz011101' is 2 out of 3 [May 10 18:25:24] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101 [May 10 18:25:24] VERBOSE[25684] logger.c: Looking for 700 in xyz (domain pbxtest.acecape.com) [May 10 18:25:24] DEBUG[25684] chan_sip.c: *** Our native formats are 0x4 (ulaw) [May 10 18:25:24] DEBUG[25684] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [May 10 18:25:24] DEBUG[25684] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [May 10 18:25:24] DEBUG[25684] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 10 18:25:24] DEBUG[25684] chan_sip.c: This channel will not be able to handle video. [May 10 18:25:24] DEBUG[25684] chan_sip.c: build_route: Contact hop: [May 10 18:25:24] VERBOSE[25684] logger.c: list_route: hop: [May 10 18:25:24] DEBUG[25684] chan_sip.c: SIP/xyz011101-082013b0: New call is still down.... Trying... [May 10 18:25:24] VERBOSE[25684] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK701caede755F0C61;received=66.114.80.25 From: "poly work" ;tag=D7107017-7B3CDF5C To: Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 CSeq: 2 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 10 18:25:24] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-082013b0 [May 10 18:25:24] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:24] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:24] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:24] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:24] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:24] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:24] DEBUG[25719] pbx.c: Launching 'Park' [May 10 18:25:24] VERBOSE[25719] logger.c: -- Executing [700@xyz:1] Park("SIP/xyz011101-082013b0", "") in new stack [May 10 18:25:24] DEBUG[25719] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-082013b0 [May 10 18:25:24] DEBUG[25719] chan_sip.c: SIP answering channel: SIP/xyz011101-082013b0 [May 10 18:25:24] DEBUG[25719] chan_sip.c: Setting framing from config on incoming call [May 10 18:25:24] DEBUG[25719] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [May 10 18:25:24] DEBUG[25719] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [May 10 18:25:24] VERBOSE[25719] logger.c: Audio is at 66.114.80.26 port 40892 [May 10 18:25:24] VERBOSE[25719] logger.c: Adding codec 0x4 (ulaw) to SDP [May 10 18:25:24] VERBOSE[25719] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [May 10 18:25:24] DEBUG[25719] chan_sip.c: -- Done with adding codecs to SDP [May 10 18:25:24] DEBUG[25719] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [May 10 18:25:24] VERBOSE[25719] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK701caede755F0C61;received=66.114.80.25 From: "poly work" ;tag=D7107017-7B3CDF5C To: ;tag=as2578b71c Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 CSeq: 2 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 213 v=0 o=root 25553 25553 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 40892 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [May 10 18:25:24] DEBUG[25719] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #329 [May 10 18:25:24] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:24] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:24] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:24] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> ACK sip:700@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5dfb14c569D7B984 From: "poly work" ;tag=D7107017-7B3CDF5C To: ;tag=as2578b71c CSeq: 2 ACK Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="6bb9cd58", uri="sip:700@pbxtest.acecape.com:5060;user=phone", response="9e4fb378084fa13f8fa83b34c9c403a1", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 0: ACK sip:700@66.114.80.26 SIP/2.0 (32) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5dfb14c569D7B984 (61) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=D7107017-7B3CDF5C (75) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=as2578b71c (59) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 4: CSeq: 2 ACK (11) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 (49) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 9: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="6bb9cd58", uri="sip:700@pbxtest.acecape.com:5060;user=phone", response="9e4fb378084fa13f8fa83b34c9c403a1", algorithm=MD5 (197) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 10: Max-Forwards: 70 (16) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 11: Content-Length: 0 (17) [May 10 18:25:24] DEBUG[25684] chan_sip.c: Header 12: (0) [May 10 18:25:24] VERBOSE[25684] logger.c: --- (12 headers 0 lines) --- [May 10 18:25:24] DEBUG[25684] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 10 18:25:24] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #329 [May 10 18:25:24] DEBUG[25684] chan_sip.c: Stopping retransmission on '21afaad3-b06521bd-62299f0a@192.168.0.250' of Response 2: Match Not Found [May 10 18:25:24] DEBUG[25719] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2236 [May 10 18:25:25] VERBOSE[25719] logger.c: == Parked SIP/xyz011101-082013b0 on -1@parkedcalls. Will timeout back to extension [xyz] s, 1 in 600 seconds [May 10 18:25:25] DEBUG[25719] pbx.c: Added extension '1001' priority 1 to parkedcalls [May 10 18:25:25] VERBOSE[25719] logger.c: -- Added extension '1001' priority 1 to parkedcalls [May 10 18:25:25] DEBUG[25719] res_features.c: Notification of state change to metermaids 1001@parkedcalls [May 10 18:25:25] DEBUG[25719] devicestate.c: Notification of state change to be queued on device/channel park:1001@parkedcalls [May 10 18:25:25] DEBUG[25719] channel.c: Set channel SIP/xyz011101-082013b0 to write format slin [May 10 18:25:25] VERBOSE[25719] logger.c: -- Started music on hold, class 'default', on channel 'SIP/xyz011101-082013b0' [May 10 18:25:25] DEBUG[25719] channel.c: Scheduling timer at 160 sample intervals [May 10 18:25:25] DEBUG[25719] pbx.c: Spawn extension (xyz,s,1) exited KEEPALIVE on 'SIP/xyz011101-082013b0' [May 10 18:25:25] VERBOSE[25719] logger.c: == Spawn extension (xyz, s, 1) exited KEEPALIVE on 'SIP/xyz011101-082013b0' [May 10 18:25:25] DEBUG[25674] devicestate.c: Checking if I can find provider for "park" - number: 1001@parkedcalls [May 10 18:25:25] DEBUG[25674] res_features.c: Checking state of exten 1001 in context parkedcalls [May 10 18:25:25] DEBUG[25674] devicestate.c: Changing state for park:1001@parkedcalls - state 2 (In use) [May 10 18:25:25] DEBUG[25675] rtp.c: Ooh, format changed from unknown to ulaw [May 10 18:25:25] DEBUG[25675] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [May 10 18:25:26] DEBUG[25717] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 66.114.80.25:2235 [May 10 18:25:26] DEBUG[25717] rtp.c: Got RTCP report of 88 bytes [May 10 18:25:27] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> REFER sip:100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK6a2759df6FDA22C6 From: ;tag=3586B7C0-BD2DEC51 To: "xyz main" ;tag=as79e36426 CSeq: 2 REFER Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Refer-To: Referred-By: Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 0: REFER sip:100@66.114.80.26 SIP/2.0 (34) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK6a2759df6FDA22C6 (61) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 2: From: ;tag=3586B7C0-BD2DEC51 (57) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 3: To: "xyz main" ;tag=as79e36426 (52) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 4: CSeq: 2 REFER (13) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 8: Refer-To: (155) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 9: Referred-By: (48) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 10: Max-Forwards: 70 (16) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 11: Content-Length: 0 (17) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 12: (0) [May 10 18:25:27] VERBOSE[25684] logger.c: --- (12 headers 0 lines) --- [May 10 18:25:27] DEBUG[25684] chan_sip.c: **** Received REFER (9) - Command in SIP REFER [May 10 18:25:27] VERBOSE[25684] logger.c: Call 23816a2d3fde880f560b05385a64b744@66.114.80.26 got a SIP call transfer from caller: (REFER)! [May 10 18:25:27] DEBUG[25684] chan_sip.c: Attended transfer: Will use Replace-Call-ID : 21afaad3-b06521bd-62299f0a@192.168.0.250 (No check of from/to tags) [May 10 18:25:27] VERBOSE[25684] logger.c: SIP transfer to extension 700@xyz by xyz011101@pbxtest.acecape.com [May 10 18:25:27] DEBUG[25684] chan_sip.c: SIP attended transfer: Transferer channel SIP/xyz011101-081e3d18, transferee channel SIP/12128121207010001-081dd788 [May 10 18:25:27] DEBUG[25684] chan_sip.c: Got SIP transfer, applying to bridged peer 'SIP/12128121207010001-081dd788' [May 10 18:25:27] DEBUG[25684] chan_sip.c: Looking for callid 21afaad3-b06521bd-62299f0a@192.168.0.250 (fromtag D7107017-7B3CDF5C totag as2578b71c) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Matched INCOMING call - their tag is D7107017-7B3CDF5C Our tag is as2578b71c [May 10 18:25:27] VERBOSE[25684] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 202 Accepted Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK6a2759df6FDA22C6;received=66.114.80.25 From: ;tag=3586B7C0-BD2DEC51 To: "xyz main" ;tag=as79e36426 Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 CSeq: 2 REFER User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 10 18:25:27] DEBUG[25684] chan_sip.c: SIP attended transfer: Error: No target channel [May 10 18:25:27] DEBUG[25684] chan_sip.c: SIP attended transfer: trying to bridge SIP/xyz011101-082013b0 and SIP/12128121207010001-081dd788 [May 10 18:25:27] DEBUG[25684] chan_sip.c: Sip transfer:-------------------- [May 10 18:25:27] DEBUG[25684] chan_sip.c: -- Transferer to PBX channel: SIP/xyz011101-081e3d18 State Up [May 10 18:25:27] DEBUG[25684] chan_sip.c: -- Transferer to PBX second channel (target): SIP/xyz011101-082013b0 State Up [May 10 18:25:27] DEBUG[25684] chan_sip.c: -- Bridged call to transferee: SIP/12128121207010001-081dd788 State Up [May 10 18:25:27] DEBUG[25684] chan_sip.c: -- No target second channel --- [May 10 18:25:27] DEBUG[25684] chan_sip.c: -- END Sip transfer:-------------------- [May 10 18:25:27] DEBUG[25684] chan_sip.c: SIP transfer: Four channels to handle [May 10 18:25:27] DEBUG[25684] channel.c: Set channel SIP/xyz011101-082013b0 to write format ulaw [May 10 18:25:27] VERBOSE[25684] logger.c: -- Stopped music on hold on SIP/xyz011101-082013b0 [May 10 18:25:27] DEBUG[25684] channel.c: Scheduling timer at 0 sample intervals [May 10 18:25:27] DEBUG[25684] channel.c: Set channel SIP/12128121207010001-081dd788 to write format ulaw [May 10 18:25:27] VERBOSE[25684] logger.c: -- Stopped music on hold on SIP/12128121207010001-081dd788 [May 10 18:25:27] DEBUG[25684] channel.c: Scheduling timer at 0 sample intervals [May 10 18:25:27] DEBUG[25684] chan_sip.c: SIP transfer: trying to masquerade SIP/12128121207010001-081dd788 into SIP/xyz011101-082013b0 [May 10 18:25:27] DEBUG[25684] channel.c: Planning to masquerade channel SIP/12128121207010001-081dd788 into the structure of SIP/xyz011101-082013b0 [May 10 18:25:27] DEBUG[25684] channel.c: Done planning to masquerade channel SIP/12128121207010001-081dd788 into the structure of SIP/xyz011101-082013b0 [May 10 18:25:27] DEBUG[25684] chan_sip.c: SIP transfer: Succeeded to masquerade channels. [May 10 18:25:27] DEBUG[25684] chan_sip.c: Strict routing enforced for session 23816a2d3fde880f560b05385a64b744@66.114.80.26 [May 10 18:25:27] VERBOSE[25684] logger.c: set_destination: Parsing for address/port to send to [May 10 18:25:27] VERBOSE[25684] logger.c: set_destination: set destination to 192.168.0.250, port 5060 [May 10 18:25:27] VERBOSE[25684] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1109: NOTIFY sip:xyz011101@192.168.0.250 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK03e3976c;rport From: "xyz main" ;tag=as79e36426 To: ;tag=3586B7C0-BD2DEC51 Contact: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 CSeq: 103 NOTIFY User-Agent: AcePBX Max-Forwards: 70 Event: refer;id=2 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 16 SIP/2.0 200 OK --- [May 10 18:25:27] DEBUG[25684] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #331 [May 10 18:25:27] DEBUG[25684] chan_sip.c: SIP attended transfer: Unlocking channel SIP/xyz011101-082013b0 [May 10 18:25:27] DEBUG[25675] channel.c: Actually Masquerading SIP/12128121207010001-081dd788(6) into the structure of SIP/xyz011101-082013b0(6) [May 10 18:25:27] DEBUG[25675] channel.c: Got clone lock for masquerade on 'SIP/12128121207010001-081dd788' at 0x81ded80 [May 10 18:25:27] DEBUG[25675] chan_sip.c: SIP Fixup: New owner for dialogue 21afaad3-b06521bd-62299f0a@192.168.0.250: SIP/12128121207010001-081dd788 (Old parent: SIP/12128121207010001-081dd788) [May 10 18:25:27] DEBUG[25675] chan_sip.c: Hangup call SIP/12128121207010001-081dd788, SIP callid 21afaad3-b06521bd-62299f0a@192.168.0.250) [May 10 18:25:27] DEBUG[25675] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup [May 10 18:25:27] DEBUG[25675] chan_sip.c: Updating call counter for incoming call [May 10 18:25:27] DEBUG[25675] chan_sip.c: Call from peer 'xyz011101' removed from call limit 3 [May 10 18:25:27] DEBUG[25675] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101 [May 10 18:25:27] VERBOSE[25675] logger.c: Scheduling destruction of SIP dialog '21afaad3-b06521bd-62299f0a@192.168.0.250' in 32000 ms (Method: ACK) [May 10 18:25:27] DEBUG[25675] chan_sip.c: Strict routing enforced for session 21afaad3-b06521bd-62299f0a@192.168.0.250 [May 10 18:25:27] VERBOSE[25675] logger.c: set_destination: Parsing for address/port to send to [May 10 18:25:27] VERBOSE[25675] logger.c: set_destination: set destination to 192.168.0.250, port 5060 [May 10 18:25:27] VERBOSE[25675] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1109: BYE sip:xyz011101@192.168.0.250 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44cde217;rport From: ;tag=as2578b71c To: "poly work" ;tag=D7107017-7B3CDF5C Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 CSeq: 102 BYE User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [May 10 18:25:27] DEBUG[25675] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #333 [May 10 18:25:27] DEBUG[25675] channel.c: Putting channel SIP/12128121207010001-081dd788 in 4/4 formats [May 10 18:25:27] DEBUG[25675] chan_sip.c: SIP Fixup: New owner for dialogue 003094c4-4b890009-2ede8432-0c55ca51@192.168.0.217: SIP/12128121207010001-081dd788 (Old parent: SIP/xyz011101-082013b0) [May 10 18:25:27] DEBUG[25675] channel.c: Released clone lock on 'SIP/xyz011101-082013b0' [May 10 18:25:27] DEBUG[25675] channel.c: Done Masquerading SIP/12128121207010001-081dd788 (6) [May 10 18:25:27] DEBUG[25675] res_features.c: MOH on parked call stopped by outside source. Restarting. [May 10 18:25:27] DEBUG[25675] channel.c: Set channel SIP/12128121207010001-081dd788 to write format slin [May 10 18:25:27] VERBOSE[25675] logger.c: -- Started music on hold, class 'default', on channel 'SIP/12128121207010001-081dd788' [May 10 18:25:27] DEBUG[25675] channel.c: Scheduling timer at 160 sample intervals [May 10 18:25:27] DEBUG[25675] rtp.c: RTP Transmission error of packet to 0.0.0.0:0: Invalid argument [May 10 18:25:27] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:27] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:27] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:27] DEBUG[25717] rtp.c: Oooh, something is weird, backing out [May 10 18:25:27] DEBUG[25717] channel.c: Bridge stops because we're zombie or need a soft hangup: c0=SIP/xyz011101-082013b0, c1=SIP/xyz011101-081e3d18, flags: Yes,Yes,No,No [May 10 18:25:27] DEBUG[25717] channel.c: Bridge stops bridging channels SIP/xyz011101-082013b0 and SIP/xyz011101-081e3d18 [May 10 18:25:27] DEBUG[25717] channel.c: Hanging up channel 'SIP/xyz011101-081e3d18' [May 10 18:25:27] DEBUG[25717] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup [May 10 18:25:27] DEBUG[25717] chan_sip.c: Updating call counter for outgoing call [May 10 18:25:27] DEBUG[25717] chan_sip.c: Call to peer 'xyz011101' removed from call limit 3 [May 10 18:25:27] DEBUG[25717] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101 [May 10 18:25:27] DEBUG[25717] chan_sip.c: SIP Transfer: Not hanging up right now... Rescheduling hangup for 23816a2d3fde880f560b05385a64b744@66.114.80.26. [May 10 18:25:27] VERBOSE[25717] logger.c: Scheduling destruction of SIP dialog '23816a2d3fde880f560b05385a64b744@66.114.80.26' in 32000 ms (Method: REFER) [May 10 18:25:27] DEBUG[25717] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081e3d18 [May 10 18:25:27] DEBUG[25717] rtp.c: Channel '' has no RTP, not doing anything [May 10 18:25:27] DEBUG[25717] app_dial.c: Exiting with DIALSTATUS=ANSWER. [May 10 18:25:27] DEBUG[25717] res_agi.c: SIP/xyz011101-082013b0 hungup [May 10 18:25:27] DEBUG[25717] pbx.c: Spawn extension (xyz,111,2) exited non-zero on 'SIP/xyz011101-082013b0' [May 10 18:25:27] VERBOSE[25717] logger.c: == Spawn extension (xyz, 111, 2) exited non-zero on 'SIP/xyz011101-082013b0' [May 10 18:25:27] DEBUG[25717] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [May 10 18:25:27] DEBUG[25717] cdr_pgsql.c: cdr_pgsql: SQL command executed: INSERT INTO voice_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-05-10 18:25:24','"poly work" <111>','111','111','xyz', 'SIP/xyz011101-082013b0','SIP/xyz011101-081e3d18','Park','',3,3,'ANSWERED',3,'','1178835917.15','') [May 10 18:25:27] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:27] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:27] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [May 10 18:25:27] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:27] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:27] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [May 10 18:25:27] DEBUG[25717] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [May 10 18:25:27] DEBUG[25717] cdr_pgsql.c: cdr_pgsql: SQL command executed: INSERT INTO voice_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-05-10 18:25:19','"poly work" <111>','111','s','xyz', 'SIP/xyz011101-081e3d18','SIP/xyz011101-081e3d18','','',8,6,'ANSWERED',3,'','1178835919.16','') [May 10 18:25:27] DEBUG[25717] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [May 10 18:25:27] DEBUG[25717] cdr_pgsql.c: cdr_pgsql: SQL command executed: INSERT INTO voice_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-05-10 18:25:17','"poly work" <111>','111','111','xyz', 'SIP/12128121207010001-081dd788','SIP/xyz011101-081e3d18','Dial','SIP/xyz011101|15|',10,6,'ANSWERED',3,'','1178835917.15','2:12128121207010001>111') [May 10 18:25:27] DEBUG[25717] channel.c: Hanging up zombie 'SIP/xyz011101-082013b0' [May 10 18:25:27] DEBUG[25717] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-082013b0 [May 10 18:25:27] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:27] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:27] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [May 10 18:25:27] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK03e3976c;rport From: "xyz main" ;tag=as79e36426 To: ;tag=3586B7C0-BD2DEC51 CSeq: 103 NOTIFY Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: Event: refer;id=2 User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Content-Length: 0 <-------------> [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK03e3976c;rport (63) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 2: From: "xyz main" ;tag=as79e36426 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=3586B7C0-BD2DEC51 (55) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 4: CSeq: 103 NOTIFY (16) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 7: Event: refer;id=2 (17) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 9: Content-Length: 0 (17) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 10: (0) [May 10 18:25:27] VERBOSE[25684] logger.c: --- (10 headers 0 lines) --- [May 10 18:25:27] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #331 [May 10 18:25:27] DEBUG[25684] chan_sip.c: Stopping retransmission on '23816a2d3fde880f560b05385a64b744@66.114.80.26' of Request 103: Match Not Found [May 10 18:25:27] VERBOSE[25684] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived [May 10 18:25:27] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> BYE sip:100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKe49adee9F7AED5B8 From: ;tag=3586B7C0-BD2DEC51 To: "xyz main" ;tag=as79e36426 CSeq: 3 BYE Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 0: BYE sip:100@66.114.80.26 SIP/2.0 (32) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKe49adee9F7AED5B8 (61) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 2: From: ;tag=3586B7C0-BD2DEC51 (57) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 3: To: "xyz main" ;tag=as79e36426 (52) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 4: CSeq: 3 BYE (11) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 8: Max-Forwards: 70 (16) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 9: Content-Length: 0 (17) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 10: (0) [May 10 18:25:27] VERBOSE[25684] logger.c: --- (10 headers 0 lines) --- [May 10 18:25:27] DEBUG[25684] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [May 10 18:25:27] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1109 (NAT) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Setting SIP_ALREADYGONE on dialog 23816a2d3fde880f560b05385a64b744@66.114.80.26 [May 10 18:25:27] VERBOSE[25684] logger.c: Scheduling destruction of SIP dialog '23816a2d3fde880f560b05385a64b744@66.114.80.26' in 32000 ms (Method: BYE) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Received bye, no owner, selfdestruct soon. [May 10 18:25:27] VERBOSE[25684] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKe49adee9F7AED5B8;received=66.114.80.25 From: ;tag=3586B7C0-BD2DEC51 To: "xyz main" ;tag=as79e36426 Call-ID: 23816a2d3fde880f560b05385a64b744@66.114.80.26 CSeq: 3 BYE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 10 18:25:27] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44cde217;rport From: ;tag=as2578b71c To: "poly work" ;tag=D7107017-7B3CDF5C CSeq: 102 BYE Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Content-Length: 0 <-------------> [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44cde217;rport (63) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 2: From: ;tag=as2578b71c (61) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 3: To: "poly work" ;tag=D7107017-7B3CDF5C (73) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 4: CSeq: 102 BYE (13) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 21afaad3-b06521bd-62299f0a@192.168.0.250 (49) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 8: Content-Length: 0 (17) [May 10 18:25:27] DEBUG[25684] chan_sip.c: Header 9: (0) [May 10 18:25:27] VERBOSE[25684] logger.c: --- (9 headers 0 lines) --- [May 10 18:25:27] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #333 [May 10 18:25:27] DEBUG[25684] chan_sip.c: Stopping retransmission on '21afaad3-b06521bd-62299f0a@192.168.0.250' of Request 102: Match Not Found [May 10 18:25:27] VERBOSE[25684] logger.c: SIP Response message for INCOMING dialog BYE arrived [May 10 18:25:27] VERBOSE[25684] logger.c: Really destroying SIP dialog '21afaad3-b06521bd-62299f0a@192.168.0.250' Method: ACK [May 10 18:25:31] DEBUG[25684] chan_sip.c: Auto destroying SIP dialog '164832a2-8f7c3334-57a0c4b5@192.168.0.250' [May 10 18:25:31] DEBUG[25684] chan_sip.c: Destroying SIP dialog 164832a2-8f7c3334-57a0c4b5@192.168.0.250 [May 10 18:25:31] VERBOSE[25684] logger.c: Really destroying SIP dialog '164832a2-8f7c3334-57a0c4b5@192.168.0.250' Method: REGISTER [May 10 18:25:33] DEBUG[25684] chan_sip.c: Auto destroying SIP dialog 'ab784484-102ef5c6-b4d330df@192.168.0.250' [May 10 18:25:33] DEBUG[25684] chan_sip.c: Destroying SIP dialog ab784484-102ef5c6-b4d330df@192.168.0.250 [May 10 18:25:33] VERBOSE[25684] logger.c: Really destroying SIP dialog 'ab784484-102ef5c6-b4d330df@192.168.0.250' Method: REGISTER [May 10 18:25:39] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> INVITE sip:1001@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8dc9c6633894EEDA From: "poly work" ;tag=19750871-9B78A1AE To: CSeq: 1 INVITE Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1178813062 1178813062 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 m=audio 2238 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 0: INVITE sip:1001@pbxtest.acecape.com:5060;user=phone SIP/2.0 (59) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8dc9c6633894EEDA (61) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=19750871-9B78A1AE (75) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 3: To: (45) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 4: CSeq: 1 INVITE (14) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 (49) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 11: Max-Forwards: 70 (16) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 12: Content-Type: application/sdp (29) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 13: Content-Length: 251 (19) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 14: (0) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: o=- 1178813062 1178813062 IN IP4 192.168.0.250 (46) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: s=Polycom IP Phone (18) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: m=audio 2238 RTP/AVP 0 8 18 101 (31) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=sendrecv (10) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:39] VERBOSE[25684] logger.c: --- (14 headers 11 lines) --- [May 10 18:25:39] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:39] DEBUG[25684] chan_sip.c: Allocating new SIP dialog for 2c4dcecd-154df2a7-f28616ac@192.168.0.250 - INVITE (With RTP) [May 10 18:25:39] DEBUG[25684] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 10 18:25:39] DEBUG[25684] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [May 10 18:25:39] DEBUG[25684] chan_sip.c: Found SIP option: -100rel- [May 10 18:25:39] DEBUG[25684] chan_sip.c: Matched SIP option: 100rel [May 10 18:25:39] DEBUG[25684] chan_sip.c: Found SIP option: -replaces- [May 10 18:25:39] DEBUG[25684] chan_sip.c: Matched SIP option: replaces [May 10 18:25:39] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1109 (NAT) [May 10 18:25:39] VERBOSE[25684] logger.c: Using INVITE request as basis request - 2c4dcecd-154df2a7-f28616ac@192.168.0.250 [May 10 18:25:39] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:39] VERBOSE[25684] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8dc9c6633894EEDA;received=66.114.80.25 From: "poly work" ;tag=19750871-9B78A1AE To: ;tag=as2caf28ee Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 CSeq: 1 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="acepbx.com", nonce="615fcca1" Content-Length: 0 <------------> [May 10 18:25:39] DEBUG[25684] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #336 [May 10 18:25:39] VERBOSE[25684] logger.c: Scheduling destruction of SIP dialog '2c4dcecd-154df2a7-f28616ac@192.168.0.250' in 32000 ms (Method: INVITE) [May 10 18:25:39] VERBOSE[25684] logger.c: Found user 'xyz011101' [May 10 18:25:39] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> ACK sip:1001@pbxtest.acecape.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8dc9c6633894EEDA From: "poly work" ;tag=19750871-9B78A1AE To: ;tag=as2caf28ee CSeq: 1 ACK Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 0: ACK sip:1001@pbxtest.acecape.com:5060 SIP/2.0 (45) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8dc9c6633894EEDA (61) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=19750871-9B78A1AE (75) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=as2caf28ee (60) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 4: CSeq: 1 ACK (11) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 (49) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 9: Max-Forwards: 70 (16) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 10: Content-Length: 0 (17) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 11: (0) [May 10 18:25:39] VERBOSE[25684] logger.c: --- (11 headers 0 lines) --- [May 10 18:25:39] DEBUG[25684] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 10 18:25:39] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #336 [May 10 18:25:39] DEBUG[25684] chan_sip.c: Stopping retransmission on '2c4dcecd-154df2a7-f28616ac@192.168.0.250' of Response 1: Match Not Found [May 10 18:25:39] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> INVITE sip:1001@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKa0cb060621F62AB From: "poly work" ;tag=19750871-9B78A1AE To: CSeq: 2 INVITE Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="615fcca1", uri="sip:1001@pbxtest.acecape.com:5060;user=phone", response="937ee7b77c35db6c717badb5497d7b65", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1178813062 1178813062 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 m=audio 2238 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 0: INVITE sip:1001@pbxtest.acecape.com:5060;user=phone SIP/2.0 (59) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKa0cb060621F62AB (60) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=19750871-9B78A1AE (75) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 3: To: (45) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 4: CSeq: 2 INVITE (14) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 (49) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="615fcca1", uri="sip:1001@pbxtest.acecape.com:5060;user=phone", response="937ee7b77c35db6c717badb5497d7b65", algorithm=MD5 (198) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 12: Max-Forwards: 70 (16) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 13: Content-Type: application/sdp (29) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 14: Content-Length: 251 (19) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 15: (0) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: v=0 (3) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: o=- 1178813062 1178813062 IN IP4 192.168.0.250 (46) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: s=Polycom IP Phone (18) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: t=0 0 (5) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: m=audio 2238 RTP/AVP 0 8 18 101 (31) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=sendrecv (10) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [May 10 18:25:39] VERBOSE[25684] logger.c: --- (15 headers 11 lines) --- [May 10 18:25:39] DEBUG[25684] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 10 18:25:39] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1109 (NAT) [May 10 18:25:39] VERBOSE[25684] logger.c: Using INVITE request as basis request - 2c4dcecd-154df2a7-f28616ac@192.168.0.250 [May 10 18:25:39] DEBUG[25684] chan_sip.c: Setting NAT on RTP to On [May 10 18:25:39] VERBOSE[25684] logger.c: Found user 'xyz011101' [May 10 18:25:39] VERBOSE[25684] logger.c: Found RTP audio format 0 [May 10 18:25:39] VERBOSE[25684] logger.c: Found RTP audio format 8 [May 10 18:25:39] VERBOSE[25684] logger.c: Found RTP audio format 18 [May 10 18:25:39] VERBOSE[25684] logger.c: Found RTP audio format 101 [May 10 18:25:39] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2238 [May 10 18:25:39] VERBOSE[25684] logger.c: Found description format PCMU for ID 0 [May 10 18:25:39] VERBOSE[25684] logger.c: Found description format PCMA for ID 8 [May 10 18:25:39] VERBOSE[25684] logger.c: Found description format G729 for ID 18 [May 10 18:25:39] VERBOSE[25684] logger.c: Found description format telephone-event for ID 101 [May 10 18:25:39] DEBUG[25684] chan_sip.c: T38 state changed to 0 on channel [May 10 18:25:39] VERBOSE[25684] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [May 10 18:25:39] VERBOSE[25684] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [May 10 18:25:39] VERBOSE[25684] logger.c: Peer audio RTP is at port 192.168.0.250:2238 [May 10 18:25:39] DEBUG[25684] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Checking SIP call limits for device xyz011101 [May 10 18:25:39] DEBUG[25684] chan_sip.c: Updating call counter for incoming call [May 10 18:25:39] DEBUG[25684] chan_sip.c: Call from peer 'xyz011101' is 1 out of 3 [May 10 18:25:39] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101 [May 10 18:25:39] VERBOSE[25684] logger.c: Looking for 1001 in xyz (domain pbxtest.acecape.com) [May 10 18:25:39] DEBUG[25684] chan_sip.c: *** Our native formats are 0x4 (ulaw) [May 10 18:25:39] DEBUG[25684] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [May 10 18:25:39] DEBUG[25684] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [May 10 18:25:39] DEBUG[25684] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 10 18:25:39] DEBUG[25684] chan_sip.c: This channel will not be able to handle video. [May 10 18:25:39] DEBUG[25684] chan_sip.c: build_route: Contact hop: [May 10 18:25:39] VERBOSE[25684] logger.c: list_route: hop: [May 10 18:25:39] DEBUG[25684] chan_sip.c: SIP/xyz011101-081dc208: New call is still down.... Trying... [May 10 18:25:39] VERBOSE[25684] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKa0cb060621F62AB;received=66.114.80.25 From: "poly work" ;tag=19750871-9B78A1AE To: Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 CSeq: 2 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 10 18:25:39] DEBUG[25684] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081dc208 [May 10 18:25:39] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:39] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:39] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:39] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:39] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:39] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:39] DEBUG[25720] pbx.c: Launching 'ParkedCall' [May 10 18:25:39] VERBOSE[25720] logger.c: -- Executing [1001@xyz:1] ParkedCall("SIP/xyz011101-081dc208", "1001") in new stack [May 10 18:25:39] DEBUG[25720] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081dc208 [May 10 18:25:39] DEBUG[25720] chan_sip.c: SIP answering channel: SIP/xyz011101-081dc208 [May 10 18:25:39] DEBUG[25720] chan_sip.c: Setting framing from config on incoming call [May 10 18:25:39] DEBUG[25720] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [May 10 18:25:39] DEBUG[25720] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [May 10 18:25:39] VERBOSE[25720] logger.c: Audio is at 66.114.80.26 port 46402 [May 10 18:25:39] VERBOSE[25720] logger.c: Adding codec 0x4 (ulaw) to SDP [May 10 18:25:39] VERBOSE[25720] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [May 10 18:25:39] DEBUG[25720] chan_sip.c: -- Done with adding codecs to SDP [May 10 18:25:39] DEBUG[25720] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [May 10 18:25:39] VERBOSE[25720] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKa0cb060621F62AB;received=66.114.80.25 From: "poly work" ;tag=19750871-9B78A1AE To: ;tag=as4789c01c Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 CSeq: 2 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 213 v=0 o=root 25553 25553 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 46402 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [May 10 18:25:39] DEBUG[25720] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #338 [May 10 18:25:39] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:39] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:39] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 2 (In use) [May 10 18:25:39] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> ACK sip:1001@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKe5795a6f4E8DCB96 From: "poly work" ;tag=19750871-9B78A1AE To: ;tag=as4789c01c CSeq: 2 ACK Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="615fcca1", uri="sip:1001@pbxtest.acecape.com:5060;user=phone", response="937ee7b77c35db6c717badb5497d7b65", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 0: ACK sip:1001@66.114.80.26 SIP/2.0 (33) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKe5795a6f4E8DCB96 (61) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=19750871-9B78A1AE (75) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=as4789c01c (60) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 4: CSeq: 2 ACK (11) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 (49) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 9: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="615fcca1", uri="sip:1001@pbxtest.acecape.com:5060;user=phone", response="937ee7b77c35db6c717badb5497d7b65", algorithm=MD5 (198) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 10: Max-Forwards: 70 (16) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 11: Content-Length: 0 (17) [May 10 18:25:39] DEBUG[25684] chan_sip.c: Header 12: (0) [May 10 18:25:39] VERBOSE[25684] logger.c: --- (12 headers 0 lines) --- [May 10 18:25:39] DEBUG[25684] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 10 18:25:39] DEBUG[25684] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #338 [May 10 18:25:39] DEBUG[25684] chan_sip.c: Stopping retransmission on '2c4dcecd-154df2a7-f28616ac@192.168.0.250' of Response 2: Match Not Found [May 10 18:25:39] DEBUG[25720] channel.c: Set channel SIP/xyz011101-081dc208 to write format gsm [May 10 18:25:39] DEBUG[25720] rtp.c: Ooh, format changed from unknown to ulaw [May 10 18:25:39] DEBUG[25720] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [May 10 18:25:39] DEBUG[25720] channel.c: Scheduling timer at 160 sample intervals [May 10 18:25:39] VERBOSE[25720] logger.c: -- Playing 'pbx-invalidpark' (language 'en') [May 10 18:25:39] DEBUG[25720] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2238 [May 10 18:25:41] DEBUG[25720] rtp.c: Got RTCP report of 88 bytes [May 10 18:25:44] VERBOSE[25684] logger.c: <--- SIP read from 66.114.80.25:1109 ---> BYE sip:1001@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK2455a8f9E07E08 From: "poly work" ;tag=19750871-9B78A1AE To: ;tag=as4789c01c CSeq: 3 BYE Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="615fcca1", uri="sip:1001@pbxtest.acecape.com:5060;user=phone", response="482d2f17e8c14281f6f402fda8899155", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 0: BYE sip:1001@66.114.80.26 SIP/2.0 (33) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK2455a8f9E07E08 (59) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 2: From: "poly work" ;tag=19750871-9B78A1AE (75) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 3: To: ;tag=as4789c01c (60) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 4: CSeq: 3 BYE (11) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 5: Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 (49) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 6: Contact: (38) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.1.0052 (54) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 8: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="615fcca1", uri="sip:1001@pbxtest.acecape.com:5060;user=phone", response="482d2f17e8c14281f6f402fda8899155", algorithm=MD5 (198) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 9: Max-Forwards: 70 (16) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 10: Content-Length: 0 (17) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Header 11: (0) [May 10 18:25:44] VERBOSE[25684] logger.c: --- (11 headers 0 lines) --- [May 10 18:25:44] DEBUG[25684] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [May 10 18:25:44] VERBOSE[25684] logger.c: Sending to 66.114.80.25 : 1109 (NAT) [May 10 18:25:44] DEBUG[25684] chan_sip.c: Setting SIP_ALREADYGONE on dialog 2c4dcecd-154df2a7-f28616ac@192.168.0.250 [May 10 18:25:44] DEBUG[25684] chan_sip.c: Received bye, issuing owner hangup [May 10 18:25:44] VERBOSE[25684] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1109 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK2455a8f9E07E08;received=66.114.80.25 From: "poly work" ;tag=19750871-9B78A1AE To: ;tag=as4789c01c Call-ID: 2c4dcecd-154df2a7-f28616ac@192.168.0.250 CSeq: 3 BYE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [May 10 18:25:44] WARNING[25720] res_features.c: ast_streamfile of pbx-invalidpark failed on SIP/xyz011101-081dc208 [May 10 18:25:44] VERBOSE[25720] logger.c: -- Channel SIP/xyz011101-081dc208 tried to talk to nonexistent parked call 1001 [May 10 18:25:44] DEBUG[25720] pbx.c: Spawn extension (xyz,1001,1) exited non-zero on 'SIP/xyz011101-081dc208' [May 10 18:25:44] VERBOSE[25720] logger.c: == Spawn extension (xyz, 1001, 1) exited non-zero on 'SIP/xyz011101-081dc208' [May 10 18:25:44] DEBUG[25720] channel.c: Scheduling timer at 0 sample intervals [May 10 18:25:44] DEBUG[25720] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [May 10 18:25:44] DEBUG[25720] cdr_pgsql.c: cdr_pgsql: SQL command executed: INSERT INTO voice_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-05-10 18:25:39','"poly work" <111>','111','1001','xyz', 'SIP/xyz011101-081dc208','','ParkedCall','1001',5,5,'ANSWERED',3,'','1178835939.18','') [May 10 18:25:44] DEBUG[25720] channel.c: Hanging up channel 'SIP/xyz011101-081dc208' [May 10 18:25:44] DEBUG[25720] chan_sip.c: Hangup call SIP/xyz011101-081dc208, SIP callid 2c4dcecd-154df2a7-f28616ac@192.168.0.250) [May 10 18:25:44] DEBUG[25720] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup [May 10 18:25:44] DEBUG[25720] chan_sip.c: Updating call counter for incoming call [May 10 18:25:44] DEBUG[25720] chan_sip.c: Call from peer 'xyz011101' removed from call limit 3 [May 10 18:25:44] DEBUG[25720] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101 [May 10 18:25:44] DEBUG[25720] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081dc208 [May 10 18:25:44] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:44] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:44] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [May 10 18:25:44] DEBUG[25674] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [May 10 18:25:44] DEBUG[25674] chan_sip.c: Checking device state for peer xyz011101 [May 10 18:25:44] DEBUG[25674] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [May 10 18:25:45] VERBOSE[25684] logger.c: Really destroying SIP dialog '2c4dcecd-154df2a7-f28616ac@192.168.0.250' Method: BYE [May 10 18:25:46] VERBOSE[25714] logger.c: -- Remote UNIX connection disconnected