[Jan 11 15:28:19] DEBUG[6261] chan_sip.c: = Found Their Call ID: cbf526d4-137d9b52-1eecc60d@192.168.0.250 Their Tag 9904BF00-D82AABB3 Our tag: as3ac4b448 [Jan 11 15:28:19] DEBUG[6261] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 11 15:28:19] DEBUG[6261] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011102 [Jan 11 15:28:19] DEBUG[6257] devicestate.c: No provider found, checking channel drivers for SIP - xyz011102 [Jan 11 15:28:19] DEBUG[6257] chan_sip.c: Checking device state for peer xyz011102 [Jan 11 15:28:19] DEBUG[6257] devicestate.c: Changing state for SIP/xyz011102 - state 1 (Not in use) [Jan 11 15:28:24] DEBUG[6261] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Jan 11 15:28:24] DEBUG[6261] chan_sip.c: = Found Their Call ID: 4783eeba2c8b0732727136a90836df42@66.114.80.26 Their Tag Our tag: as283e0cb6 [Jan 11 15:28:24] DEBUG[6261] chan_sip.c: Stopping retransmission on '4783eeba2c8b0732727136a90836df42@66.114.80.26' of Request 102: Match Not Found [Jan 11 15:28:24] VERBOSE[6261] logger.c: Really destroying SIP dialog '4783eeba2c8b0732727136a90836df42@66.114.80.26' Method: NOTIFY [Jan 11 15:28:36] VERBOSE[6261] logger.c: <--- SIP read from 66.114.80.25:1063 ---> INVITE sip:12128121208@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbd88622723303664 From: "poly work" ;tag=80D4FE19-66B03790 To: CSeq: 1 INVITE Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1168544078 1168544078 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2254 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 <-------------> [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 0: INVITE sip:12128121208@pbxtest.acecape.com:5060;user=phone SIP/2.0 (66) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbd88622723303664 (61) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 2: From: "poly work" ;tag=80D4FE19-66B03790 (75) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 3: To: (52) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 4: CSeq: 1 INVITE (14) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 5: Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 (49) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 6: Contact: (38) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 11: Max-Forwards: 70 (16) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 13: Content-Length: 251 (19) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 14: (0) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: v=0 (3) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: o=- 1168544078 1168544078 IN IP4 192.168.0.250 (46) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: s=Polycom IP Phone (18) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: t=0 0 (5) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=sendrecv (10) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: m=audio 2254 RTP/AVP 0 8 18 101 (31) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 11 15:28:36] VERBOSE[6261] logger.c: --- (14 headers 11 lines) --- [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: = No match Their Call ID: cbf526d4-137d9b52-1eecc60d@192.168.0.250 Their Tag 9904BF00-D82AABB3 Our tag: as3ac4b448 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: = No match Their Call ID: 134a90df-6c031fd5-c60acabc@192.168.0.250 Their Tag AFFB8EBB-5AD2257A Our tag: as7025e5e4 [Jan 11 15:28:36] WARNING[6261] rtp.c: Unable to set TOS to 184 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Setting NAT on RTP to On [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Allocating new SIP dialog for 990b065d-e754ac83-157b1d62@192.168.0.250 - INVITE (With RTP) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Found SIP option: -100rel- [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Matched SIP option: 100rel [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Found SIP option: -replaces- [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Matched SIP option: replaces [Jan 11 15:28:36] VERBOSE[6261] logger.c: Sending to 66.114.80.25 : 1063 (NAT) [Jan 11 15:28:36] VERBOSE[6261] logger.c: Using INVITE request as basis request - 990b065d-e754ac83-157b1d62@192.168.0.250 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Setting NAT on RTP to On [Jan 11 15:28:36] VERBOSE[6261] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1063 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbd88622723303664;received=66.114.80.25 From: "poly work" ;tag=80D4FE19-66B03790 To: ;tag=as7c9404aa Call-ID: 990b065d-e754ac83-157b1d62@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="472fbb40" Content-Length: 0 <------------> [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #95 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Scheduling destruction of SIP dialog '990b065d-e754ac83-157b1d62@192.168.0.250' in 32000 ms (Method: INVITE) [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found user 'xyz011101' [Jan 11 15:28:36] VERBOSE[6261] logger.c: <--- SIP read from 66.114.80.25:1063 ---> ACK sip:12128121208@pbxtest.acecape.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbd88622723303664 From: "poly work" ;tag=80D4FE19-66B03790 To: ;tag=as7c9404aa CSeq: 1 ACK Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Max-Forwards: 70 Content-Length: 0 <-------------> [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 0: ACK sip:12128121208@pbxtest.acecape.com:5060 SIP/2.0 (52) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbd88622723303664 (61) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 2: From: "poly work" ;tag=80D4FE19-66B03790 (75) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 3: To: ;tag=as7c9404aa (67) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 4: CSeq: 1 ACK (11) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 5: Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 (49) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 6: Contact: (38) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 10: Content-Length: 0 (17) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 11: (0) [Jan 11 15:28:36] VERBOSE[6261] logger.c: --- (11 headers 0 lines) --- [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: = Found Their Call ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Their Tag 80D4FE19-66B03790 Our tag: as7c9404aa [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #95 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Stopping retransmission on '990b065d-e754ac83-157b1d62@192.168.0.250' of Response 1: Match Not Found [Jan 11 15:28:36] VERBOSE[6261] logger.c: <--- SIP read from 66.114.80.25:1063 ---> INVITE sip:12128121208@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5bf1b06e8463809F From: "poly work" ;tag=80D4FE19-66B03790 To: CSeq: 2 INVITE Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="472fbb40", uri="sip:12128121208@pbxtest.acecape.com:5060;user=phone", response="23abffaf56f11eb366d73043c36757f6", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1168544078 1168544078 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2254 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 <-------------> [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 0: INVITE sip:12128121208@pbxtest.acecape.com:5060;user=phone SIP/2.0 (66) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5bf1b06e8463809F (61) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 2: From: "poly work" ;tag=80D4FE19-66B03790 (75) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 3: To: (52) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 4: CSeq: 2 INVITE (14) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 5: Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 (49) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 6: Contact: (38) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="472fbb40", uri="sip:12128121208@pbxtest.acecape.com:5060;user=phone", response="23abffaf56f11eb366d73043c36757f6", algorithm=MD5 (205) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 12: Max-Forwards: 70 (16) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 14: Content-Length: 251 (19) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Header 15: (0) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: v=0 (3) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: o=- 1168544078 1168544078 IN IP4 192.168.0.250 (46) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: s=Polycom IP Phone (18) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: t=0 0 (5) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=sendrecv (10) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: m=audio 2254 RTP/AVP 0 8 18 101 (31) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 11 15:28:36] VERBOSE[6261] logger.c: --- (15 headers 11 lines) --- [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: = Found Their Call ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Their Tag 80D4FE19-66B03790 Our tag: as7c9404aa [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 11 15:28:36] VERBOSE[6261] logger.c: Sending to 66.114.80.25 : 1063 (NAT) [Jan 11 15:28:36] VERBOSE[6261] logger.c: Using INVITE request as basis request - 990b065d-e754ac83-157b1d62@192.168.0.250 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Setting NAT on RTP to On [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found user 'xyz011101' [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found RTP audio format 0 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found RTP audio format 8 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found RTP audio format 18 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found RTP audio format 101 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Peer audio RTP is at port 192.168.0.250:2254 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found description format PCMU for ID 0 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found description format PCMA for ID 8 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found description format G729 for ID 18 [Jan 11 15:28:36] VERBOSE[6261] logger.c: Found description format telephone-event for ID 101 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: T38 state changed to 0 on channel [Jan 11 15:28:36] VERBOSE[6261] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 11 15:28:36] VERBOSE[6261] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 11 15:28:36] VERBOSE[6261] logger.c: Peer audio RTP is at port 192.168.0.250:2254 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Checking SIP call limits for device xyz011101 [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: Updating call counter for incoming call [Jan 11 15:28:36] VERBOSE[6261] logger.c: Looking for 12128121208 in xyz (domain pbxtest.acecape.com) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: This channel will not be able to handle video. [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: build_route: Contact hop: [Jan 11 15:28:36] VERBOSE[6261] logger.c: list_route: hop: [Jan 11 15:28:36] DEBUG[6261] chan_sip.c: SIP/xyz011101-081c62f0: New call is still down.... Trying... [Jan 11 15:28:36] VERBOSE[6261] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1063 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5bf1b06e8463809F;received=66.114.80.25 From: "poly work" ;tag=80D4FE19-66B03790 To: Call-ID: 990b065d-e754ac83-157b1d62@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 <------------> [Jan 11 15:28:36] DEBUG[6261] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c62f0 [Jan 11 15:28:36] DEBUG[6257] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Jan 11 15:28:36] DEBUG[6257] chan_sip.c: Checking device state for peer xyz011101 [Jan 11 15:28:36] DEBUG[6257] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Jan 11 15:28:36] DEBUG[6276] pbx.c: Launching 'Set' [Jan 11 15:28:36] VERBOSE[6276] logger.c: -- Executing [12128121208@xyz:1] Set("SIP/xyz011101-081c62f0", "TIMEOUT(absolute)=7200") in new stack [Jan 11 15:28:36] VERBOSE[6276] logger.c: -- Channel will hangup at 2007-01-11 22:28:36 UTC. [Jan 11 15:28:36] DEBUG[6276] pbx.c: Launching 'Set' [Jan 11 15:28:36] VERBOSE[6276] logger.c: -- Executing [12128121208@xyz:2] Set("SIP/xyz011101-081c62f0", "AGISIGHUP=0") in new stack [Jan 11 15:28:36] DEBUG[6276] pbx.c: Launching 'AGI' [Jan 11 15:28:36] VERBOSE[6276] logger.c: -- Executing [12128121208@xyz:3] AGI("SIP/xyz011101-081c62f0", "callprocessing.agi") in new stack [Jan 11 15:28:36] VERBOSE[6276] logger.c: -- Launched AGI Script /usr/local/asterisk/var/lib/asterisk/agi-bin/callprocessing.agi [Jan 11 15:28:38] DEBUG[6276] pbx.c: Function result is 'xyz011101' [Jan 11 15:28:39] VERBOSE[6276] logger.c: -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=2:xyz011101>12128121208) [Jan 11 15:28:39] VERBOSE[6276] logger.c: -- AGI Script Executing Application: (Set) Options: (CDR(accountcode)=M:19) [Jan 11 15:28:39] VERBOSE[6276] logger.c: -- AGI Script Executing Application: (Set) Options: (MUSICCLASS()=xyz) [Jan 11 15:28:39] VERBOSE[6276] logger.c: -- AGI Script Executing Application: (Answer) Options: ((null)) [Jan 11 15:28:39] DEBUG[6276] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c62f0 [Jan 11 15:28:39] DEBUG[6276] chan_sip.c: SIP answering channel: SIP/xyz011101-081c62f0 [Jan 11 15:28:39] DEBUG[6276] chan_sip.c: Setting framing from config on incoming call [Jan 11 15:28:39] DEBUG[6276] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jan 11 15:28:39] DEBUG[6276] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 11 15:28:39] VERBOSE[6276] logger.c: Audio is at 66.114.80.26 port 48212 [Jan 11 15:28:39] VERBOSE[6276] logger.c: Adding codec 0x4 (ulaw) to SDP [Jan 11 15:28:39] VERBOSE[6276] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Jan 11 15:28:39] DEBUG[6276] chan_sip.c: -- Done with adding codecs to SDP [Jan 11 15:28:39] DEBUG[6276] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 11 15:28:39] DEBUG[6276] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jan 11 15:28:39] VERBOSE[6276] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1063 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5bf1b06e8463809F;received=66.114.80.25 From: "poly work" ;tag=80D4FE19-66B03790 To: ;tag=as6b903c6a Call-ID: 990b065d-e754ac83-157b1d62@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: 238 v=0 o=root 6276 6276 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 48212 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jan 11 15:28:39] DEBUG[6276] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #97 [Jan 11 15:28:39] DEBUG[6257] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Jan 11 15:28:39] DEBUG[6257] chan_sip.c: Checking device state for peer xyz011101 [Jan 11 15:28:39] DEBUG[6257] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Jan 11 15:28:39] VERBOSE[6261] logger.c: <--- SIP read from 66.114.80.25:1063 ---> ACK sip:12128121208@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8697ba7b55E65A28 From: "poly work" ;tag=80D4FE19-66B03790 To: ;tag=as6b903c6a CSeq: 2 ACK Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="472fbb40", uri="sip:12128121208@pbxtest.acecape.com:5060;user=phone", response="23abffaf56f11eb366d73043c36757f6", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 0: ACK sip:12128121208@66.114.80.26 SIP/2.0 (40) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8697ba7b55E65A28 (61) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 2: From: "poly work" ;tag=80D4FE19-66B03790 (75) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 3: To: ;tag=as6b903c6a (67) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 4: CSeq: 2 ACK (11) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 5: Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 (49) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 6: Contact: (38) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 9: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="472fbb40", uri="sip:12128121208@pbxtest.acecape.com:5060;user=phone", response="23abffaf56f11eb366d73043c36757f6", algorithm=MD5 (205) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 10: Max-Forwards: 70 (16) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 11: Content-Length: 0 (17) [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Header 12: (0) [Jan 11 15:28:39] VERBOSE[6261] logger.c: --- (12 headers 0 lines) --- [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: = Found Their Call ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Their Tag 80D4FE19-66B03790 Our tag: as6b903c6a [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #97 [Jan 11 15:28:39] DEBUG[6261] chan_sip.c: Stopping retransmission on '990b065d-e754ac83-157b1d62@192.168.0.250' of Response 2: Match Not Found [Jan 11 15:28:39] DEBUG[6276] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2254 [Jan 11 15:28:40] DEBUG[6276] channel.c: Set channel SIP/xyz011101-081c62f0 to write format gsm [Jan 11 15:28:40] DEBUG[6276] rtp.c: Ooh, format changed from unknown to ulaw [Jan 11 15:28:40] DEBUG[6276] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jan 11 15:28:40] VERBOSE[6276] logger.c: -- Playing 'xyz/mainmenu' (language 'en') [Jan 11 15:28:42] DEBUG[6261] chan_sip.c: Auto destroying SIP dialog '134a90df-6c031fd5-c60acabc@192.168.0.250' [Jan 11 15:28:42] DEBUG[6261] chan_sip.c: Destroying SIP dialog 134a90df-6c031fd5-c60acabc@192.168.0.250 [Jan 11 15:28:42] VERBOSE[6261] logger.c: Really destroying SIP dialog '134a90df-6c031fd5-c60acabc@192.168.0.250' Method: REGISTER [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:44] DEBUG[6276] rtp.c: Sending dtmf: 42 (*), at 66.114.80.25 [Jan 11 15:28:44] DTMF[6276] channel.c: DTMF begin '*' received on SIP/xyz011101-081c62f0 [Jan 11 15:28:44] DEBUG[6276] sched.c: Request to schedule in the past?!?! [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:44] DEBUG[6276] rtp.c: Sending dtmf: 42 (*), at 66.114.80.25 [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:44] DEBUG[6276] rtp.c: - RTP 2833 Event: 0000000a (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: Sending dtmf: 49 (1), at 66.114.80.25 [Jan 11 15:28:45] DTMF[6276] channel.c: DTMF begin '1' received on SIP/xyz011101-081c62f0 [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: Sending dtmf: 49 (1), at 66.114.80.25 [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:45] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000001 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: Sending dtmf: 50 (2), at 66.114.80.25 [Jan 11 15:28:46] DTMF[6276] channel.c: DTMF begin '2' received on SIP/xyz011101-081c62f0 [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: Sending dtmf: 50 (2), at 66.114.80.25 [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:46] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000002 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: Sending dtmf: 51 (3), at 66.114.80.25 [Jan 11 15:28:47] DTMF[6276] channel.c: DTMF begin '3' received on SIP/xyz011101-081c62f0 [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: Sending dtmf: 51 (3), at 66.114.80.25 [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:47] DEBUG[6276] rtp.c: - RTP 2833 Event: 00000003 (len = 4) [Jan 11 15:28:48] NOTICE[6261] chan_sip.c: -- Re-registration for pbxtest@66.114.83.7 [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Allocating new SIP dialog for 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 - REGISTER (No RTP) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Scheduled a registration timeout for 66.114.83.7 id #99 [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: >>> Re-using Auth data for pbxtest@66.114.83.7 [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 0: REGISTER sip:66.114.83.7 SIP/2.0 (32) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK7c39987b;rport (63) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 2: From: ;tag=as336d8693 (46) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 3: To: (29) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 4: Call-ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 (54) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 5: CSeq: 105 REGISTER (18) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 6: User-Agent: AcePBX (18) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 7: Max-Forwards: 70 (16) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 8: Authorization: Digest username="pbxtest", realm="acepbx.com", algorithm=MD5, uri="sip:66.114.83.7", nonce="45a69e59c8f1a138a4d6904cb3bc08ce0fbf1c39", response="ae24650edf547a3559bddf1cc873066f", opaque="", qop=auth, cnonce="294f6c65", nc=00000003 (246) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 9: Expires: 120 (12) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 10: Contact: (29) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 11: Event: registration (19) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 12: Content-Length: 0 (17) [Jan 11 15:28:48] VERBOSE[6261] logger.c: REGISTER 13 headers, 0 lines [Jan 11 15:28:48] VERBOSE[6261] logger.c: REGISTER attempt 1 to pbxtest@66.114.83.7 [Jan 11 15:28:48] VERBOSE[6261] logger.c: Reliably Transmitting (NAT) to 66.114.83.7:5060: REGISTER sip:66.114.83.7 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK7c39987b;rport From: ;tag=as336d8693 To: Call-ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 CSeq: 105 REGISTER User-Agent: AcePBX Max-Forwards: 70 Authorization: Digest username="pbxtest", realm="acepbx.com", algorithm=MD5, uri="sip:66.114.83.7", nonce="45a69e59c8f1a138a4d6904cb3bc08ce0fbf1c39", response="ae24650edf547a3559bddf1cc873066f", opaque="", qop=auth, cnonce="294f6c65", nc=00000003 Expires: 120 Contact: Event: registration Content-Length: 0 --- [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #100 [Jan 11 15:28:48] VERBOSE[6261] logger.c: <--- SIP read from 66.114.83.7:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK7c39987b;rport=5060 From: ;tag=as336d8693 To: Call-ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 CSeq: 105 REGISTER Content-Length: 0 <-------------> [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK7c39987b;rport=5060 (68) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 2: From: ;tag=as336d8693 (46) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 3: To: (29) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 4: Call-ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 (54) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 5: CSeq: 105 REGISTER (18) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 6: Content-Length: 0 (17) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 7: (0) [Jan 11 15:28:48] VERBOSE[6261] logger.c: --- (7 headers 0 lines) --- [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: = Found Their Call ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 Their Tag Our tag: as336d8693 [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: *** SIP TIMER: Cancelling retransmission #100 - REGISTER (got response) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26' Request 105: Found [Jan 11 15:28:48] VERBOSE[6261] logger.c: <--- SIP read from 66.114.83.7:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK7c39987b;rport=5060 From: ;tag=as336d8693 To: ;tag=bb62d7e482cc1e58bd69683900d56829.80af Call-ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 CSeq: 105 REGISTER Contact: ;expires=120 Content-Length: 0 <-------------> [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK7c39987b;rport=5060 (68) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 2: From: ;tag=as336d8693 (46) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 3: To: ;tag=bb62d7e482cc1e58bd69683900d56829.80af (71) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 4: Call-ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 (54) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 5: CSeq: 105 REGISTER (18) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 6: Contact: ;expires=120 (41) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 7: Content-Length: 0 (17) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 8: (0) [Jan 11 15:28:48] VERBOSE[6261] logger.c: --- (8 headers 0 lines) --- [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: = Found Their Call ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 Their Tag Our tag: as336d8693 [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Stopping retransmission on '4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26' of Request 105: Match Not Found [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Registration successful [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Cancelling timeout 99 [Jan 11 15:28:48] VERBOSE[6261] logger.c: Scheduling destruction of SIP dialog '4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26' in 32000 ms (Method: REGISTER) [Jan 11 15:28:48] NOTICE[6261] chan_sip.c: Outbound Registration: Expiry for 66.114.83.7 is 120 sec (Scheduling reregistration in 105 s) [Jan 11 15:28:48] VERBOSE[6261] logger.c: <--- SIP read from 66.114.80.25:1063 ---> BYE sip:12128121208@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKd0cb28d12D8690C6 From: "poly work" ;tag=80D4FE19-66B03790 To: ;tag=as6b903c6a CSeq: 3 BYE Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="472fbb40", uri="sip:12128121208@pbxtest.acecape.com:5060;user=phone", response="28bf5ce6fc3a30e079fb1443c3ab6fb9", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 0: BYE sip:12128121208@66.114.80.26 SIP/2.0 (40) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKd0cb28d12D8690C6 (61) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 2: From: "poly work" ;tag=80D4FE19-66B03790 (75) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 3: To: ;tag=as6b903c6a (67) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 4: CSeq: 3 BYE (11) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 5: Call-ID: 990b065d-e754ac83-157b1d62@192.168.0.250 (49) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 6: Contact: (38) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 8: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="472fbb40", uri="sip:12128121208@pbxtest.acecape.com:5060;user=phone", response="28bf5ce6fc3a30e079fb1443c3ab6fb9", algorithm=MD5 (205) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 10: Content-Length: 0 (17) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Header 11: (0) [Jan 11 15:28:48] VERBOSE[6261] logger.c: --- (11 headers 0 lines) --- [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: = No match Their Call ID: 4eb52523083832ee7f5fa8a378a14bd0@66.114.80.26 Their Tag bb62d7e482cc1e58bd69683900d56829.80af Our tag: as336d8693 [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: = Found Their Call ID: 990b065d-e754ac83-157b1d62@192.168.0.250 Their Tag 80D4FE19-66B03790 Our tag: as6b903c6a [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 11 15:28:48] VERBOSE[6261] logger.c: Sending to 66.114.80.25 : 1063 (NAT) [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Setting SIP_ALREADYGONE on dialog 990b065d-e754ac83-157b1d62@192.168.0.250 [Jan 11 15:28:48] DEBUG[6261] chan_sip.c: Received bye, issuing owner hangup [Jan 11 15:28:48] VERBOSE[6261] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1063 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKd0cb28d12D8690C6;received=66.114.80.25 From: "poly work" ;tag=80D4FE19-66B03790 To: ;tag=as6b903c6a Call-ID: 990b065d-e754ac83-157b1d62@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 <------------> [Jan 11 15:28:48] DEBUG[6276] channel.c: Set channel SIP/xyz011101-081c62f0 to write format ulaw [Jan 11 15:28:48] DEBUG[6276] res_agi.c: SIP/xyz011101-081c62f0 hungup [Jan 11 15:28:48] DEBUG[6276] pbx.c: Spawn extension (xyz,12128121208,3) exited non-zero on 'SIP/xyz011101-081c62f0' [Jan 11 15:28:48] VERBOSE[6276] logger.c: == Spawn extension (xyz, 12128121208, 3) exited non-zero on 'SIP/xyz011101-081c62f0' [Jan 11 15:28:48] DEBUG[6276] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [Jan 11 15:28:48] DEBUG[6276] 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-01-11 15:28:36','"poly work" <111>','111','12128121208','xyz', 'SIP/xyz011101-081c62f0','','Answer','',12,9,'ANSWERED',3,'M:19','1168547316.1','2:xyz011101>12128121208') [Jan 11 15:28:48] DEBUG[6276] channel.c: Hanging up channel 'SIP/xyz011101-081c62f0' [Jan 11 15:28:48] DEBUG[6276] chan_sip.c: Hangup call SIP/xyz011101-081c62f0, SIP callid 990b065d-e754ac83-157b1d62@192.168.0.250) [Jan 11 15:28:48] DEBUG[6276] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup [Jan 11 15:28:48] DEBUG[6276] chan_sip.c: Updating call counter for incoming call [Jan 11 15:28:48] DEBUG[6276] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c62f0 [Jan 11 15:28:48] DEBUG[6257] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Jan 11 15:28:48] DEBUG[6257] chan_sip.c: Checking device state for peer xyz011101 [Jan 11 15:28:48] DEBUG[6257] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Jan 11 15:28:49] VERBOSE[6261] logger.c: Really destroying SIP dialog '990b065d-e754ac83-157b1d62@192.168.0.250' Method: BYE