<--- SIP read from 66.114.80.25:1025 ---> INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK1345f4b6D1D1D17 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: CSeq: 1 INVITE Call-ID: db655b00-6303ba6a-ee242eb1@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: 212 v=0 o=- 1170106932 1170106932 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2224 RTP/AVP 0 8 18 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 <-------------> [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 0: INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (59) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK1345f4b6D1D1D17 (60) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=AFD98CF4-D7CCD26B (75) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 3: To: (45) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 4: CSeq: 1 INVITE (14) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 5: Call-ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 (49) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 6: Contact: (38) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 11: Max-Forwards: 70 (16) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 13: Content-Length: 212 (19) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 14: (0) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: v=0 (3) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: o=- 1170106932 1170106932 IN IP4 192.168.0.250 (46) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: s=Polycom IP Phone (18) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: t=0 0 (5) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=sendrecv (10) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: m=audio 2224 RTP/AVP 0 8 18 (27) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Jan 30 14:52:24] VERBOSE[7368] logger.c: --- (14 headers 10 lines) --- [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: = No match Their Call ID: 003094c4-4b890006-5d336920-4df7e81c@192.168.0.217 Their Tag Our tag: as70d1285d [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: = No match Their Call ID: 53f729967cd10f0746876bb05a64441c@66.114.80.26 Their Tag Our tag: as6df90df2 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Setting NAT on RTP to On [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Allocating new SIP dialog for db655b00-6303ba6a-ee242eb1@192.168.0.250 - INVITE (With RTP) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Found SIP option: -100rel- [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Matched SIP option: 100rel [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Found SIP option: -replaces- [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Matched SIP option: replaces [Jan 30 14:52:24] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Jan 30 14:52:24] VERBOSE[7368] logger.c: Using INVITE request as basis request - db655b00-6303ba6a-ee242eb1@192.168.0.250 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Setting NAT on RTP to On [Jan 30 14:52:24] VERBOSE[7368] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1025 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK1345f4b6D1D1D17;received=66.114.80.25 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: ;tag=as175b5a21 Call-ID: db655b00-6303ba6a-ee242eb1@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="74ce7245" Content-Length: 0 <------------> [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #572 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Scheduling destruction of SIP dialog 'db655b00-6303ba6a-ee242eb1@192.168.0.250' in 32000 ms (Method: INVITE) [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found user 'xyz011101' [Jan 30 14:52:24] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1025 ---> ACK sip:1100@pbxtest.acecape.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK1345f4b6D1D1D17 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: ;tag=as175b5a21 CSeq: 1 ACK Call-ID: db655b00-6303ba6a-ee242eb1@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 30 14:52:24] DEBUG[7368] chan_sip.c: Header 0: ACK sip:1100@pbxtest.acecape.com:5060 SIP/2.0 (45) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK1345f4b6D1D1D17 (60) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=AFD98CF4-D7CCD26B (75) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 3: To: ;tag=as175b5a21 (60) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 4: CSeq: 1 ACK (11) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 5: Call-ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 (49) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 6: Contact: (38) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 10: Content-Length: 0 (17) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 11: (0) [Jan 30 14:52:24] VERBOSE[7368] logger.c: --- (11 headers 0 lines) --- [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: = Found Their Call ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 Their Tag AFD98CF4-D7CCD26B Our tag: as175b5a21 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #572 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Stopping retransmission on 'db655b00-6303ba6a-ee242eb1@192.168.0.250' of Response 1: Match Not Found [Jan 30 14:52:24] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1025 ---> INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK4184524512B76C9E From: "poly work" ;tag=AFD98CF4-D7CCD26B To: CSeq: 2 INVITE Call-ID: db655b00-6303ba6a-ee242eb1@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="74ce7245", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="7486139e54e44237354c7b0a5ddf77e4", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 212 v=0 o=- 1170106932 1170106932 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2224 RTP/AVP 0 8 18 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 <-------------> [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 0: INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (59) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK4184524512B76C9E (61) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=AFD98CF4-D7CCD26B (75) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 3: To: (45) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 4: CSeq: 2 INVITE (14) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 5: Call-ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 (49) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 6: Contact: (38) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="74ce7245", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="7486139e54e44237354c7b0a5ddf77e4", algorithm=MD5 (198) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 12: Max-Forwards: 70 (16) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 14: Content-Length: 212 (19) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Header 15: (0) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: v=0 (3) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: o=- 1170106932 1170106932 IN IP4 192.168.0.250 (46) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: s=Polycom IP Phone (18) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: t=0 0 (5) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=sendrecv (10) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: m=audio 2224 RTP/AVP 0 8 18 (27) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Jan 30 14:52:24] VERBOSE[7368] logger.c: --- (15 headers 10 lines) --- [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: = Found Their Call ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 Their Tag AFD98CF4-D7CCD26B Our tag: as175b5a21 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 30 14:52:24] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Jan 30 14:52:24] VERBOSE[7368] logger.c: Using INVITE request as basis request - db655b00-6303ba6a-ee242eb1@192.168.0.250 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Setting NAT on RTP to On [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found user 'xyz011101' [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found RTP audio format 0 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found RTP audio format 8 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found RTP audio format 18 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.250:2224 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found description format PCMU for ID 0 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found description format PCMA for ID 8 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Found description format G729 for ID 18 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: T38 state changed to 0 on channel [Jan 30 14:52:24] VERBOSE[7368] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 30 14:52:24] VERBOSE[7368] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jan 30 14:52:24] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.250:2224 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Checking SIP call limits for device xyz011101 [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Updating call counter for incoming call [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: Call from user 'xyz011101' is 1 out of 2 [Jan 30 14:52:24] VERBOSE[7368] logger.c: Looking for 1100 in xyz (domain pbxtest.acecape.com) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: This channel will not be able to handle video. [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: build_route: Contact hop: [Jan 30 14:52:24] VERBOSE[7368] logger.c: list_route: hop: [Jan 30 14:52:24] DEBUG[7368] chan_sip.c: SIP/xyz011101-081b9120: New call is still down.... Trying... [Jan 30 14:52:24] VERBOSE[7368] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1025 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK4184524512B76C9E;received=66.114.80.25 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: Call-ID: db655b00-6303ba6a-ee242eb1@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 30 14:52:24] DEBUG[7368] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081b9120 [Jan 30 14:52:24] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Jan 30 14:52:24] DEBUG[7359] chan_sip.c: Checking device state for peer xyz011101 [Jan 30 14:52:24] DEBUG[7359] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Jan 30 14:52:24] DEBUG[7551] pbx.c: Launching 'Set' [Jan 30 14:52:24] VERBOSE[7551] logger.c: -- Executing [1100@xyz:1] Set("SIP/xyz011101-081b9120", "TIMEOUT(absolute)=10800") in new stack [Jan 30 14:52:24] VERBOSE[7551] logger.c: -- Channel will hangup at 2007-01-30 22:52:24 UTC. [Jan 30 14:52:24] DEBUG[7551] pbx.c: Launching 'AGI' [Jan 30 14:52:24] VERBOSE[7551] logger.c: -- Executing [1100@xyz:2] AGI("SIP/xyz011101-081b9120", "callprocessing.agi") in new stack [Jan 30 14:52:24] VERBOSE[7551] logger.c: -- Launched AGI Script /usr/local/asterisk/var/lib/asterisk/agi-bin/callprocessing.agi [Jan 30 14:52:25] DEBUG[7551] pbx.c: Function result is 'xyz011101' [Jan 30 14:52:25] VERBOSE[7551] logger.c: -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=2:xyz011101>1100) [Jan 30 14:52:25] VERBOSE[7551] logger.c: -- AGI Script Executing Application: (Set) Options: (CALLERID(name)=poly work|CALLERID(num)=111) [Jan 30 14:52:25] VERBOSE[7551] logger.c: -- AGI Script Executing Application: (Dial) Options: (SIP/1212812120701100|180|) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Setting NAT on RTP to On [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: This channel will not be able to handle video. [Jan 30 14:52:25] DEBUG[7551] channel.c: Not copying variable CP_PID. [Jan 30 14:52:25] DEBUG[7551] channel.c: Not copying variable STACK-xyz-1100-2. [Jan 30 14:52:25] DEBUG[7551] channel.c: Not copying variable STACK-xyz-1100-1. [Jan 30 14:52:25] DEBUG[7551] channel.c: Not copying variable SIPCALLID. [Jan 30 14:52:25] DEBUG[7551] channel.c: Not copying variable SIPUSERAGENT. [Jan 30 14:52:25] DEBUG[7551] channel.c: Not copying variable SIPDOMAIN. [Jan 30 14:52:25] DEBUG[7551] channel.c: Not copying variable SIPURI. [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Outgoing Call for 1212812120701100 [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Updating call counter for outgoing call [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Call to peer '1212812120701100' is 5 out of 5 [Jan 30 14:52:25] DEBUG[7551] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100 [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 30 14:52:25] VERBOSE[7551] logger.c: Audio is at 66.114.80.26 port 47874 [Jan 30 14:52:25] VERBOSE[7551] logger.c: Adding codec 0x4 (ulaw) to SDP [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 14:52:25] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 0: INVITE sip:1212812120701100@192.168.0.217:5060 SIP/2.0 (54) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport (63) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 2: From: "poly work" ;tag=as362c6765 (55) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 3: To: (45) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 4: Contact: (31) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 5: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 (54) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 7: User-Agent: AcePBX (18) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 9: Date: Tue, 30 Jan 2007 19:52:25 GMT (35) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 11: Supported: replaces (19) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 13: Content-Length: 182 (19) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Header 14: (0) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: v=0 (3) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: o=root 7551 7551 IN IP4 66.114.80.26 (36) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: s=session (9) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: c=IN IP4 66.114.80.26 (21) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: t=0 0 (5) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: m=audio 47874 RTP/AVP 0 (23) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: a=ptime:20 (10) [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: Line: a=sendrecv (10) [Jan 30 14:52:25] VERBOSE[7551] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1027: INVITE sip:1212812120701100@192.168.0.217:5060 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport From: "poly work" ;tag=as362c6765 To: Contact: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 CSeq: 102 INVITE User-Agent: AcePBX Max-Forwards: 70 Date: Tue, 30 Jan 2007 19:52:25 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 182 v=0 o=root 7551 7551 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 47874 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jan 30 14:52:25] DEBUG[7551] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #574 [Jan 30 14:52:25] VERBOSE[7551] logger.c: -- Called 1212812120701100 [Jan 30 14:52:25] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100 [Jan 30 14:52:25] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100 [Jan 30 14:52:25] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 7 (Ring+Inuse) [Jan 30 14:52:26] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1027 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport From: "poly work" ;tag=as362c6765 To: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Date: Tue, 30 Jan 2007 19:52:26 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 <-------------> [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport (63) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=as362c6765 (55) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 3: To: (45) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 (54) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:52:26 GMT (35) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 7: Server: CSCO/7 (14) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 8: Contact: (50) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 9: Content-Length: 0 (17) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 10: (0) [Jan 30 14:52:26] VERBOSE[7368] logger.c: --- (10 headers 0 lines) --- [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: = Found Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag Our tag: as362c6765 [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: *** SIP TIMER: Cancelling retransmission #574 - INVITE (got response) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '15e700da7da2afd713b28b951b9fb239@66.114.80.26' Request 102: Found [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: SIP response 100 to standard invite [Jan 30 14:52:26] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1027 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport From: "poly work" ;tag=as362c6765 To: ;tag=003094c44b89004f06e90e8f-57920a19 Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Date: Tue, 30 Jan 2007 19:52:26 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 <-------------> [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport (63) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=as362c6765 (55) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 3: To: ;tag=003094c44b89004f06e90e8f-57920a19 (83) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 (54) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:52:26 GMT (35) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 7: Server: CSCO/7 (14) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 8: Contact: (50) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 9: Content-Length: 0 (17) [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: Header 10: (0) [Jan 30 14:52:26] VERBOSE[7368] logger.c: --- (10 headers 0 lines) --- [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: = Found Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag Our tag: as362c6765 [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '15e700da7da2afd713b28b951b9fb239@66.114.80.26' Request 102: Found [Jan 30 14:52:26] DEBUG[7368] chan_sip.c: SIP response 180 to standard invite [Jan 30 14:52:26] DEBUG[7368] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100-081bad28 [Jan 30 14:52:26] VERBOSE[7551] logger.c: -- SIP/1212812120701100-081bad28 is ringing [Jan 30 14:52:26] VERBOSE[7551] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1025 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK4184524512B76C9E;received=66.114.80.25 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: ;tag=as20f7a045 Call-ID: db655b00-6303ba6a-ee242eb1@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 30 14:52:26] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100 [Jan 30 14:52:26] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100 [Jan 30 14:52:26] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 7 (Ring+Inuse) [Jan 30 14:52:27] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1027 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport From: "poly work" ;tag=as362c6765 To: ;tag=003094c44b89004f06e90e8f-57920a19 Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Date: Tue, 30 Jan 2007 19:52:27 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 143 v=0 o=Cisco-SIPUA 18155 20735 IN IP4 192.168.0.217 s=SIP Call c=IN IP4 192.168.0.217 t=0 0 m=audio 18034 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK151b90ef;rport (63) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=as362c6765 (55) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 3: To: ;tag=003094c44b89004f06e90e8f-57920a19 (83) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 (54) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:52:27 GMT (35) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 7: Server: CSCO/7 (14) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 8: Contact: (50) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 9: Content-Type: application/sdp (29) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 10: Content-Length: 143 (19) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 11: (0) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Line: v=0 (3) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Line: o=Cisco-SIPUA 18155 20735 IN IP4 192.168.0.217 (46) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Line: s=SIP Call (10) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Line: c=IN IP4 192.168.0.217 (22) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Line: t=0 0 (5) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Line: m=audio 18034 RTP/AVP 0 (23) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 30 14:52:27] VERBOSE[7368] logger.c: --- (11 headers 7 lines) --- [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: = Found Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag 003094c44b89004f06e90e8f-57920a19 Our tag: as362c6765 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Acked pending invite 102 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Stopping retransmission on '15e700da7da2afd713b28b951b9fb239@66.114.80.26' of Request 102: Match Not Found [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: SIP response 200 to standard invite [Jan 30 14:52:27] VERBOSE[7368] logger.c: Found RTP audio format 0 [Jan 30 14:52:27] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.217:18034 [Jan 30 14:52:27] VERBOSE[7368] logger.c: Found description format PCMU for ID 0 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: T38 state changed to 0 on channel SIP/1212812120701100-081bad28 [Jan 30 14:52:27] VERBOSE[7368] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 30 14:52:27] VERBOSE[7368] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jan 30 14:52:27] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.217:18034 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: We have an owner, now see if we need to change this call [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Updating call counter for outgoing call [Jan 30 14:52:27] DEBUG[7368] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: build_route: Contact hop: [Jan 30 14:52:27] VERBOSE[7368] logger.c: list_route: hop: [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Strict routing enforced for session 15e700da7da2afd713b28b951b9fb239@66.114.80.26 [Jan 30 14:52:27] VERBOSE[7368] logger.c: set_destination: Parsing for address/port to send to [Jan 30 14:52:27] VERBOSE[7368] logger.c: set_destination: set destination to 192.168.0.217, port 5060 [Jan 30 14:52:27] VERBOSE[7368] logger.c: Transmitting (NAT) to 66.114.80.25:1027: ACK sip:1212812120701100@192.168.0.217:5060 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK0c846e07;rport From: "poly work" ;tag=as362c6765 To: ;tag=003094c44b89004f06e90e8f-57920a19 Contact: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 CSeq: 102 ACK User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [Jan 30 14:52:27] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100 [Jan 30 14:52:27] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100 [Jan 30 14:52:27] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 3 (Busy) [Jan 30 14:52:27] DEBUG[7551] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100-081bad28 [Jan 30 14:52:27] VERBOSE[7551] logger.c: -- SIP/1212812120701100-081bad28 answered SIP/xyz011101-081b9120 [Jan 30 14:52:27] DEBUG[7551] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081b9120 [Jan 30 14:52:27] DEBUG[7551] chan_sip.c: SIP answering channel: SIP/xyz011101-081b9120 [Jan 30 14:52:27] DEBUG[7551] chan_sip.c: Setting framing from config on incoming call [Jan 30 14:52:27] DEBUG[7551] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jan 30 14:52:27] DEBUG[7551] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Jan 30 14:52:27] VERBOSE[7551] logger.c: Audio is at 66.114.80.26 port 44178 [Jan 30 14:52:27] VERBOSE[7551] logger.c: Adding codec 0x4 (ulaw) to SDP [Jan 30 14:52:27] DEBUG[7551] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 14:52:27] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:27] DEBUG[7551] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jan 30 14:52:27] VERBOSE[7551] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1025 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK4184524512B76C9E;received=66.114.80.25 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: ;tag=as20f7a045 Call-ID: db655b00-6303ba6a-ee242eb1@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: 182 v=0 o=root 7551 7551 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 44178 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jan 30 14:52:27] DEBUG[7551] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #576 [Jan 30 14:52:27] VERBOSE[7551] logger.c: -- Packet2Packet bridging SIP/xyz011101-081b9120 and SIP/1212812120701100-081bad28 [Jan 30 14:52:27] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100 [Jan 30 14:52:27] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100 [Jan 30 14:52:27] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 3 (Busy) [Jan 30 14:52:27] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Jan 30 14:52:27] DEBUG[7359] chan_sip.c: Checking device state for peer xyz011101 [Jan 30 14:52:27] DEBUG[7359] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Jan 30 14:52:27] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1025 ---> ACK sip:1100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK93625b5224ADBE93 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: ;tag=as20f7a045 CSeq: 2 ACK Call-ID: db655b00-6303ba6a-ee242eb1@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="74ce7245", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="7486139e54e44237354c7b0a5ddf77e4", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 0: ACK sip:1100@66.114.80.26 SIP/2.0 (33) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK93625b5224ADBE93 (61) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=AFD98CF4-D7CCD26B (75) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 3: To: ;tag=as20f7a045 (60) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 4: CSeq: 2 ACK (11) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 5: Call-ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 (49) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 6: Contact: (38) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 9: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="74ce7245", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="7486139e54e44237354c7b0a5ddf77e4", algorithm=MD5 (198) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 10: Max-Forwards: 70 (16) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 11: Content-Length: 0 (17) [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Header 12: (0) [Jan 30 14:52:27] VERBOSE[7368] logger.c: --- (12 headers 0 lines) --- [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: = No match Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag 003094c44b89004f06e90e8f-57920a19 Our tag: as362c6765 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: = Found Their Call ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 Their Tag AFD98CF4-D7CCD26B Our tag: as20f7a045 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #576 [Jan 30 14:52:27] DEBUG[7368] chan_sip.c: Stopping retransmission on 'db655b00-6303ba6a-ee242eb1@192.168.0.250' of Response 2: Match Not Found [Jan 30 14:52:27] DEBUG[7551] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:18034 [Jan 30 14:52:27] DEBUG[7551] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2224 [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Auto destroying SIP dialog '003094c4-4b890006-5d336920-4df7e81c@192.168.0.217' [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Destroying SIP dialog 003094c4-4b890006-5d336920-4df7e81c@192.168.0.217 [Jan 30 14:52:28] VERBOSE[7368] logger.c: Really destroying SIP dialog '003094c4-4b890006-5d336920-4df7e81c@192.168.0.217' Method: REGISTER [Jan 30 14:52:28] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1027 ---> INVITE sip:111@66.114.80.26:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK5ef9acc1 From: ;tag=003094c44b89004f06e90e8f-57920a19 To: "poly work" ;tag=as362c6765 Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Date: Tue, 30 Jan 2007 19:52:29 GMT CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 136 v=0 o=Cisco-SIPUA 26062 2755 IN IP4 192.168.0.217 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 18034 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 0: INVITE sip:111@66.114.80.26:5060 SIP/2.0 (40) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK5ef9acc1 (58) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 2: From: ;tag=003094c44b89004f06e90e8f-57920a19 (85) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 3: To: "poly work" ;tag=as362c6765 (53) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 (54) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:52:29 GMT (35) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 6: CSeq: 101 INVITE (16) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 8: Contact: (50) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 9: Content-Type: application/sdp (29) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 10: Content-Length: 136 (19) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Header 11: (0) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Line: v=0 (3) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Line: o=Cisco-SIPUA 26062 2755 IN IP4 192.168.0.217 (45) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Line: s=SIP Call (10) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Line: c=IN IP4 0.0.0.0 (16) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Line: t=0 0 (5) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Line: m=audio 18034 RTP/AVP 0 (23) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 30 14:52:28] VERBOSE[7368] logger.c: --- (11 headers 7 lines) --- [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: = Found Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag 003094c44b89004f06e90e8f-57920a19 Our tag: as362c6765 [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 30 14:52:28] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1027 (NAT) [Jan 30 14:52:28] VERBOSE[7368] logger.c: Found RTP audio format 0 [Jan 30 14:52:28] VERBOSE[7368] logger.c: Peer audio RTP is at port 0.0.0.0:18034 [Jan 30 14:52:28] VERBOSE[7368] logger.c: Found description format PCMU for ID 0 [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: T38 state changed to 0 on channel SIP/1212812120701100-081bad28 [Jan 30 14:52:28] VERBOSE[7368] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 30 14:52:28] VERBOSE[7368] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jan 30 14:52:28] VERBOSE[7368] logger.c: Peer audio RTP is at port 0.0.0.0:18034 [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: We have an owner, now see if we need to change this call [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Got a SIP re-invite for call 15e700da7da2afd713b28b951b9fb239@66.114.80.26 [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: SIP/1212812120701100-081bad28: This call is UP.... [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Setting framing from config on incoming call [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Jan 30 14:52:28] VERBOSE[7368] logger.c: Audio is at 66.114.80.26 port 47874 [Jan 30 14:52:28] VERBOSE[7368] logger.c: Adding codec 0x4 (ulaw) to SDP [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 14:52:28] DEBUG[7368] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jan 30 14:52:28] VERBOSE[7368] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1027 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK5ef9acc1;received=66.114.80.25 From: ;tag=003094c44b89004f06e90e8f-57920a19 To: "poly work" ;tag=as362c6765 Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 CSeq: 101 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 182 v=0 o=root 7551 7552 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 47874 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jan 30 14:52:28] DEBUG[7368] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #577 [Jan 30 14:52:28] DEBUG[7551] channel.c: Set channel SIP/xyz011101-081b9120 to write format slin [Jan 30 14:52:28] VERBOSE[7551] logger.c: -- Started music on hold, class 'xyz', on channel 'SIP/xyz011101-081b9120' [Jan 30 14:52:28] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:28] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:28] DEBUG[7551] rtp.c: Ooh, format changed from unknown to ulaw [Jan 30 14:52:28] DEBUG[7551] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1027 ---> ACK sip:111@66.114.80.26:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK3e076e87 From: ;tag=003094c44b89004f06e90e8f-57920a19 To: "poly work" ;tag=as362c6765 Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Date: Tue, 30 Jan 2007 19:52:29 GMT CSeq: 101 ACK User-Agent: CSCO/7 Content-Length: 0 <-------------> [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 0: ACK sip:111@66.114.80.26:5060 SIP/2.0 (37) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK3e076e87 (58) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 2: From: ;tag=003094c44b89004f06e90e8f-57920a19 (85) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 3: To: "poly work" ;tag=as362c6765 (53) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 (54) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:52:29 GMT (35) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 6: CSeq: 101 ACK (13) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 8: Content-Length: 0 (17) [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Header 9: (0) [Jan 30 14:52:29] VERBOSE[7368] logger.c: --- (9 headers 0 lines) --- [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: = Found Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag 003094c44b89004f06e90e8f-57920a19 Our tag: as362c6765 [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #577 [Jan 30 14:52:29] DEBUG[7368] chan_sip.c: Stopping retransmission on '15e700da7da2afd713b28b951b9fb239@66.114.80.26' of Response 101: Match Not Found [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:29] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:30] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:30] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:30] DEBUG[7551] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Jan 30 14:52:30] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1025 ---> BYE sip:1100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbe633e5cF70212ED From: "poly work" ;tag=AFD98CF4-D7CCD26B To: ;tag=as20f7a045 CSeq: 3 BYE Call-ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="74ce7245", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="1607d9818e9a6eed36f1008806b5cb97", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 0: BYE sip:1100@66.114.80.26 SIP/2.0 (33) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbe633e5cF70212ED (61) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=AFD98CF4-D7CCD26B (75) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 3: To: ;tag=as20f7a045 (60) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 4: CSeq: 3 BYE (11) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 5: Call-ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 (49) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 6: Contact: (38) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 8: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="74ce7245", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="1607d9818e9a6eed36f1008806b5cb97", algorithm=MD5 (198) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 10: Content-Length: 0 (17) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 11: (0) [Jan 30 14:52:30] VERBOSE[7368] logger.c: --- (11 headers 0 lines) --- [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: = No match Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag 003094c44b89004f06e90e8f-57920a19 Our tag: as362c6765 [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: = Found Their Call ID: db655b00-6303ba6a-ee242eb1@192.168.0.250 Their Tag AFD98CF4-D7CCD26B Our tag: as20f7a045 [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 30 14:52:30] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Setting SIP_ALREADYGONE on dialog db655b00-6303ba6a-ee242eb1@192.168.0.250 [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Received bye, issuing owner hangup [Jan 30 14:52:30] VERBOSE[7368] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1025 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKbe633e5cF70212ED;received=66.114.80.25 From: "poly work" ;tag=AFD98CF4-D7CCD26B To: ;tag=as20f7a045 Call-ID: db655b00-6303ba6a-ee242eb1@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 30 14:52:30] DEBUG[7551] channel.c: Set channel SIP/xyz011101-081b9120 to write format ulaw [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Stopped music on hold on SIP/xyz011101-081b9120 [Jan 30 14:52:30] DEBUG[7551] rtp.c: Oooh, got a hangup [Jan 30 14:52:30] DEBUG[7551] channel.c: Returning from native bridge, channels: SIP/xyz011101-081b9120, SIP/1212812120701100-081bad28 [Jan 30 14:52:30] DEBUG[7551] channel.c: Hanging up channel 'SIP/1212812120701100-081bad28' [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: Hangup call SIP/1212812120701100-081bad28, SIP callid 15e700da7da2afd713b28b951b9fb239@66.114.80.26) [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: update_call_counter(1212812120701100) - decrement call limit counter on hangup [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: Updating call counter for incoming call [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: Call from user '1212812120701100' removed from call limit 5 [Jan 30 14:52:30] VERBOSE[7551] logger.c: Scheduling destruction of SIP dialog '15e700da7da2afd713b28b951b9fb239@66.114.80.26' in 32000 ms (Method: ACK) [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: Strict routing enforced for session 15e700da7da2afd713b28b951b9fb239@66.114.80.26 [Jan 30 14:52:30] VERBOSE[7551] logger.c: set_destination: Parsing for address/port to send to [Jan 30 14:52:30] VERBOSE[7551] logger.c: set_destination: set destination to 192.168.0.217, port 5060 [Jan 30 14:52:30] VERBOSE[7551] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1027: BYE sip:1212812120701100@192.168.0.217:5060 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK648f1b32;rport From: "poly work" ;tag=as362c6765 To: ;tag=003094c44b89004f06e90e8f-57920a19 Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 CSeq: 103 BYE User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #580 [Jan 30 14:52:30] DEBUG[7551] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100-081bad28 [Jan 30 14:52:30] DEBUG[7551] rtp.c: Channel '' has no RTP, not doing anything [Jan 30 14:52:30] DEBUG[7551] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 30 14:52:30] DEBUG[7551] res_agi.c: SIP/xyz011101-081b9120 hungup [Jan 30 14:52:30] DEBUG[7551] pbx.c: Spawn extension (xyz,1100,2) exited non-zero on 'SIP/xyz011101-081b9120' [Jan 30 14:52:30] VERBOSE[7551] logger.c: == Spawn extension (xyz, 1100, 2) exited non-zero on 'SIP/xyz011101-081b9120' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Macro' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [h@xyz:1] Macro("SIP/xyz011101-081b9120", "logvar|AGISTATUS") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Function result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Expression result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'GotoIf' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081b9120", "1?+1:+2") in new stack [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Goto (macro-logvar,s,2) [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Log' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081b9120", "NOTICE|"[7552]: 1170186744.22: AGISTATUS=HANGUP"") in new stack [Jan 30 14:52:30] NOTICE[7551] Ext. s: "[7552]: 1170186744.22: AGISTATUS=HANGUP" [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'NoOp' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081b9120", "") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Macro' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [h@xyz:2] Macro("SIP/xyz011101-081b9120", "logvar|DIALSTATUS") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Function result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Expression result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'GotoIf' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081b9120", "1?+1:+2") in new stack [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Goto (macro-logvar,s,2) [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Log' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081b9120", "NOTICE|"[7552]: 1170186744.22: DIALSTATUS=ANSWER"") in new stack [Jan 30 14:52:30] NOTICE[7551] Ext. s: "[7552]: 1170186744.22: DIALSTATUS=ANSWER" [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'NoOp' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081b9120", "") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Macro' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [h@xyz:3] Macro("SIP/xyz011101-081b9120", "logvar|ANSWEREDTIME") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Function result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Expression result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'GotoIf' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081b9120", "1?+1:+2") in new stack [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Goto (macro-logvar,s,2) [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Log' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081b9120", "NOTICE|"[7552]: 1170186744.22: ANSWEREDTIME=3"") in new stack [Jan 30 14:52:30] NOTICE[7551] Ext. s: "[7552]: 1170186744.22: ANSWEREDTIME=3" [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'NoOp' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081b9120", "") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Macro' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [h@xyz:4] Macro("SIP/xyz011101-081b9120", "logvar|RTPAUDIOQOS") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Function result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Expression result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'GotoIf' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081b9120", "1?+1:+2") in new stack [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Goto (macro-logvar,s,2) [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Log' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081b9120", "NOTICE|"[7552]: 1170186744.22: RTPAUDIOQOS=ssrc=1530446601;themssrc=615789787;lp=0;rxjitter=0.000233;rxcount=55;txjitter=0.000000;txcount=54;rlp=0;rtt=0.000000"") in new stack [Jan 30 14:52:30] NOTICE[7551] Ext. s: "[7552]: 1170186744.22: RTPAUDIOQOS=ssrc=1530446601;themssrc=615789787;lp=0;rxjitter=0.000233;rxcount=55;txjitter=0.000000;txcount=54;rlp=0;rtt=0.000000" [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'NoOp' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081b9120", "") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Macro' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [h@xyz:5] Macro("SIP/xyz011101-081b9120", "logvar|UNIQUEID") in new stack [Jan 30 14:52:30] DEBUG[7551] pbx.c: Function result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Expression result is '1' [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'GotoIf' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081b9120", "1?+1:+2") in new stack [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Goto (macro-logvar,s,2) [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'Log' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081b9120", "NOTICE|"[7552]: 1170186744.22: UNIQUEID=1170186744.22"") in new stack [Jan 30 14:52:30] NOTICE[7551] Ext. s: "[7552]: 1170186744.22: UNIQUEID=1170186744.22" [Jan 30 14:52:30] DEBUG[7551] pbx.c: Launching 'NoOp' [Jan 30 14:52:30] VERBOSE[7551] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081b9120", "") in new stack [Jan 30 14:52:30] DEBUG[7551] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [Jan 30 14:52:30] DEBUG[7551] 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-30 14:52:24','"poly work" <111>','111','h','xyz', 'SIP/xyz011101-081b9120','SIP/1212812120701100-081bad28','NoOp','',6,3,'ANSWERED',3,'','1170186744.22','2:xyz011101>1100') [Jan 30 14:52:30] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100 [Jan 30 14:52:30] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100 [Jan 30 14:52:30] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 3 (Busy) [Jan 30 14:52:30] VERBOSE[7368] logger.c: <--- SIP read from 66.114.80.25:1027 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK648f1b32;rport From: "poly work" ;tag=as362c6765 To: ;tag=003094c44b89004f06e90e8f-57920a19 Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Date: Tue, 30 Jan 2007 19:52:30 GMT CSeq: 103 BYE Server: CSCO/7 Content-Length: 0 <-------------> [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK648f1b32;rport (63) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" ;tag=as362c6765 (55) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 3: To: ;tag=003094c44b89004f06e90e8f-57920a19 (83) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 (54) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:52:30 GMT (35) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 6: CSeq: 103 BYE (13) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 7: Server: CSCO/7 (14) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 8: Content-Length: 0 (17) [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Header 9: (0) [Jan 30 14:52:30] VERBOSE[7368] logger.c: --- (9 headers 0 lines) --- [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: = Found Their Call ID: 15e700da7da2afd713b28b951b9fb239@66.114.80.26 Their Tag 003094c44b89004f06e90e8f-57920a19 Our tag: as362c6765 [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #580 [Jan 30 14:52:30] DEBUG[7368] chan_sip.c: Stopping retransmission on '15e700da7da2afd713b28b951b9fb239@66.114.80.26' of Request 103: Match Not Found [Jan 30 14:52:30] VERBOSE[7368] logger.c: SIP Response message for INCOMING dialog BYE arrived [Jan 30 14:52:30] VERBOSE[7368] logger.c: Really destroying SIP dialog '15e700da7da2afd713b28b951b9fb239@66.114.80.26' Method: ACK [Jan 30 14:52:30] DEBUG[7551] channel.c: Hanging up channel 'SIP/xyz011101-081b9120' [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: Hangup call SIP/xyz011101-081b9120, SIP callid db655b00-6303ba6a-ee242eb1@192.168.0.250) [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: Updating call counter for incoming call [Jan 30 14:52:30] DEBUG[7551] chan_sip.c: Call from user 'xyz011101' removed from call limit 2 [Jan 30 14:52:30] DEBUG[7551] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081b9120 [Jan 30 14:52:30] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Jan 30 14:52:30] DEBUG[7359] chan_sip.c: Checking device state for peer xyz011101 [Jan 30 14:52:30] DEBUG[7359] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Jan 30 14:52:31] VERBOSE[7368] logger.c: Really destroying SIP dialog 'db655b00-6303ba6a-ee242eb1@192.168.0.250' Method: BYE