<--- SIP read from 66.114.80.25:1025 ---> INVITE sip:100@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK582e37e21E752F9F From: "poly work" ;tag=F6081CF0-EA08F053 To: CSeq: 1 INVITE Call-ID: 24d196bc-42090316-ebcda139@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=- 1170734549 1170734549 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2262 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 <-------------> [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 0: INVITE sip:100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (58) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK582e37e21E752F9F (61) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=F6081CF0-EA08F053 (75) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 3: To: (44) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 4: CSeq: 1 INVITE (14) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 24d196bc-42090316-ebcda139@192.168.0.250 (49) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 11: Max-Forwards: 70 (16) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 13: Content-Length: 251 (19) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Header 14: (0) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: o=- 1170734549 1170734549 IN IP4 192.168.0.250 (46) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: s=Polycom IP Phone (18) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: a=sendrecv (10) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: m=audio 2262 RTP/AVP 0 8 18 101 (31) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 14:05:34] VERBOSE[28216] logger.c: --- (14 headers 11 lines) --- [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Allocating new SIP dialog for 24d196bc-42090316-ebcda139@192.168.0.250 - INVITE (With RTP) [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Found SIP option: -100rel- [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Matched SIP option: 100rel [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Found SIP option: -replaces- [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Matched SIP option: replaces [Feb 6 14:05:34] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Feb 6 14:05:34] VERBOSE[28216] logger.c: Using INVITE request as basis request - 24d196bc-42090316-ebcda139@192.168.0.250 [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:05:34] VERBOSE[28216] 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=z9hG4bK582e37e21E752F9F;received=66.114.80.25 From: "poly work" ;tag=F6081CF0-EA08F053 To: ;tag=as77301ea0 Call-ID: 24d196bc-42090316-ebcda139@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="1bf09b1c" Content-Length: 0 <------------> [Feb 6 14:05:34] DEBUG[28216] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #73 [Feb 6 14:05:34] VERBOSE[28216] logger.c: Scheduling destruction of SIP dialog '24d196bc-42090316-ebcda139@192.168.0.250' in 32000 ms (Method: INVITE) [Feb 6 14:05:34] VERBOSE[28216] logger.c: Found user 'xyz011101' [Feb 6 14:05:35] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1025 ---> ACK sip:100@pbxtest.acecape.com:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK582e37e21E752F9F From: "poly work" ;tag=F6081CF0-EA08F053 To: ;tag=as77301ea0 CSeq: 1 ACK Call-ID: 24d196bc-42090316-ebcda139@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 <-------------> [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 0: ACK sip:100@pbxtest.acecape.com:5060 SIP/2.0 (44) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK582e37e21E752F9F (61) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=F6081CF0-EA08F053 (75) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=as77301ea0 (59) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 4: CSeq: 1 ACK (11) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 24d196bc-42090316-ebcda139@192.168.0.250 (49) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 11: (0) [Feb 6 14:05:35] VERBOSE[28216] logger.c: --- (11 headers 0 lines) --- [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: = Found Their Call ID: 24d196bc-42090316-ebcda139@192.168.0.250 Their Tag F6081CF0-EA08F053 Our tag: as77301ea0 [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #73 [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Stopping retransmission on '24d196bc-42090316-ebcda139@192.168.0.250' of Response 1: Match Not Found [Feb 6 14:05:35] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1025 ---> INVITE sip:100@pbxtest.acecape.com:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK19c6bced325A844A From: "poly work" ;tag=F6081CF0-EA08F053 To: CSeq: 2 INVITE Call-ID: 24d196bc-42090316-ebcda139@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="1bf09b1c", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="0caa5841ebda431fcf3f2fd74eed3bfa", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1170734549 1170734549 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2262 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 <-------------> [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 0: INVITE sip:100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (58) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK19c6bced325A844A (61) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=F6081CF0-EA08F053 (75) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 3: To: (44) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 4: CSeq: 2 INVITE (14) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 24d196bc-42090316-ebcda139@192.168.0.250 (49) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="1bf09b1c", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="0caa5841ebda431fcf3f2fd74eed3bfa", algorithm=MD5 (197) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 12: Max-Forwards: 70 (16) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 14: Content-Length: 251 (19) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Header 15: (0) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: o=- 1170734549 1170734549 IN IP4 192.168.0.250 (46) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: s=Polycom IP Phone (18) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: a=sendrecv (10) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: m=audio 2262 RTP/AVP 0 8 18 101 (31) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 14:05:35] VERBOSE[28216] logger.c: --- (15 headers 11 lines) --- [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: = Found Their Call ID: 24d196bc-42090316-ebcda139@192.168.0.250 Their Tag F6081CF0-EA08F053 Our tag: as77301ea0 [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 6 14:05:35] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Feb 6 14:05:35] VERBOSE[28216] logger.c: Using INVITE request as basis request - 24d196bc-42090316-ebcda139@192.168.0.250 [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found user 'xyz011101' [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found RTP audio format 0 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found RTP audio format 8 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found RTP audio format 18 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found RTP audio format 101 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.250:2262 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found description format PCMU for ID 0 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found description format PCMA for ID 8 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found description format G729 for ID 18 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Found description format telephone-event for ID 101 [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: T38 state changed to 0 on channel [Feb 6 14:05:35] VERBOSE[28216] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Feb 6 14:05:35] VERBOSE[28216] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 6 14:05:35] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.250:2262 [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Checking SIP call limits for device xyz011101 [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Updating call counter for incoming call [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: Call from user 'xyz011101' is 1 out of 3 [Feb 6 14:05:35] VERBOSE[28216] logger.c: Looking for 100 in xyz (domain pbxtest.acecape.com) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: This channel will not be able to handle video. [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: build_route: Contact hop: [Feb 6 14:05:35] VERBOSE[28216] logger.c: list_route: hop: [Feb 6 14:05:35] DEBUG[28216] chan_sip.c: SIP/xyz011101-081ae8a8: New call is still down.... Trying... [Feb 6 14:05:35] VERBOSE[28216] 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=z9hG4bK19c6bced325A844A;received=66.114.80.25 From: "poly work" ;tag=F6081CF0-EA08F053 To: Call-ID: 24d196bc-42090316-ebcda139@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 <------------> [Feb 6 14:05:35] DEBUG[28216] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081ae8a8 [Feb 6 14:05:35] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Feb 6 14:05:35] DEBUG[28205] chan_sip.c: Checking device state for peer xyz011101 [Feb 6 14:05:35] DEBUG[28205] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Feb 6 14:05:35] DEBUG[28240] pbx.c: Launching 'Set' [Feb 6 14:05:35] VERBOSE[28240] logger.c: -- Executing [100@xyz:1] Set("SIP/xyz011101-081ae8a8", "TIMEOUT(absolute)=10800") in new stack [Feb 6 14:05:35] VERBOSE[28240] logger.c: -- Channel will hangup at 2007-02-06 22:05:35 UTC. [Feb 6 14:05:35] DEBUG[28240] pbx.c: Function result is '0' [Feb 6 14:05:35] DEBUG[28240] pbx.c: Launching 'NoOp' [Feb 6 14:05:35] VERBOSE[28240] logger.c: -- Executing [100@xyz:2] NoOp("SIP/xyz011101-081ae8a8", "0") in new stack [Feb 6 14:05:35] DEBUG[28240] pbx.c: Launching 'AGI' [Feb 6 14:05:35] VERBOSE[28240] logger.c: -- Executing [100@xyz:3] AGI("SIP/xyz011101-081ae8a8", "callprocessing.agi") in new stack [Feb 6 14:05:35] VERBOSE[28240] logger.c: -- Launched AGI Script /usr/local/asterisk/var/lib/asterisk/agi-bin/callprocessing.agi [Feb 6 14:05:35] DEBUG[28240] pbx.c: Function result is 'xyz011101' [Feb 6 14:05:36] VERBOSE[28240] logger.c: -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=2:xyz011101>100) [Feb 6 14:05:36] VERBOSE[28240] logger.c: -- AGI Script Executing Application: (Set) Options: (CALLERID(name)=poly work|CALLERID(num)=111) [Feb 6 14:05:36] VERBOSE[28240] logger.c: -- AGI Script Executing Application: (MixMonitor) Options: (/var/spool/asterisk/monitor/02062007-140535-111-100.WAV|bW(+1)|/var/lib/asterisk/agi-bin/_UTILS/MixMonitor.sh /var/spool/asterisk/monitor/02062007-140535-111-100.WAV /var/spool/asterisk/recordings/xyz/02062007-140535-111-100.WAV &) [Feb 6 14:05:36] DEBUG[28240] channel.c: Spy MixMonitor added to channel SIP/xyz011101-081ae8a8 [Feb 6 14:05:36] VERBOSE[28243] logger.c: == Begin MixMonitor Recording SIP/xyz011101-081ae8a8 [Feb 6 14:05:36] VERBOSE[28240] logger.c: -- AGI Script Executing Application: (Dial) Options: (SIP/12128121207010001|180|) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: This channel will not be able to handle video. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable MIXMONITOR_FILENAME. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable CP_PID. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable STACK-xyz-100-3. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable STACK-xyz-100-2. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable STACK-xyz-100-1. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable SIPCALLID. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable SIPUSERAGENT. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable SIPDOMAIN. [Feb 6 14:05:36] DEBUG[28240] channel.c: Not copying variable SIPURI. [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Outgoing Call for 12128121207010001 [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Updating call counter for outgoing call [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Call to peer '12128121207010001' is 1 out of 3 [Feb 6 14:05:36] DEBUG[28240] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001 [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Feb 6 14:05:36] VERBOSE[28240] logger.c: Audio is at 66.114.80.26 port 40280 [Feb 6 14:05:36] VERBOSE[28240] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: -- Done with adding codecs to SDP [Feb 6 14:05:36] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 0: INVITE sip:12128121207010001@192.168.0.217:5060 SIP/2.0 (55) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport (63) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 2: From: "poly work" ;tag=as7b4ff713 (55) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 3: To: (46) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 4: Contact: (31) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 5: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 (54) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 7: User-Agent: AcePBX (18) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 9: Date: Tue, 06 Feb 2007 19:05:36 GMT (35) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 11: Supported: replaces (19) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 13: Content-Length: 157 (19) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Header 14: (0) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: v=0 (3) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: o=root 28240 28240 IN IP4 66.114.80.26 (38) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: s=session (9) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: c=IN IP4 66.114.80.26 (21) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: m=audio 40280 RTP/AVP 0 (23) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: a=ptime:20 (10) [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: Line: a=sendrecv (10) [Feb 6 14:05:36] VERBOSE[28240] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1028: INVITE sip:12128121207010001@192.168.0.217:5060 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport From: "poly work" ;tag=as7b4ff713 To: Contact: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 CSeq: 102 INVITE User-Agent: AcePBX Max-Forwards: 70 Date: Tue, 06 Feb 2007 19:05:36 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 157 v=0 o=root 28240 28240 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 40280 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv --- [Feb 6 14:05:36] DEBUG[28240] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #75 [Feb 6 14:05:36] VERBOSE[28240] logger.c: -- Called 12128121207010001 [Feb 6 14:05:36] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:05:36] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:05:36] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 6 (Ringing) [Feb 6 14:05:36] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1028 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport From: "poly work" ;tag=as7b4ff713 To: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Date: Tue, 06 Feb 2007 19:05:37 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 <-------------> [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport (63) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=as7b4ff713 (55) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 3: To: (46) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 (54) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:05:37 GMT (35) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 7: Server: CSCO/7 (14) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 8: Contact: (51) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: Header 10: (0) [Feb 6 14:05:36] VERBOSE[28216] logger.c: --- (10 headers 0 lines) --- [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: = Found Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag Our tag: as7b4ff713 [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: *** SIP TIMER: Cancelling retransmission #75 - INVITE (got response) [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '322c33f5339516b169f66f393394e38a@66.114.80.26' Request 102: Found [Feb 6 14:05:36] DEBUG[28216] chan_sip.c: SIP response 100 to standard invite [Feb 6 14:05:37] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1028 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport From: "poly work" ;tag=as7b4ff713 To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Date: Tue, 06 Feb 2007 19:05:37 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 <-------------> [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport (63) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=as7b4ff713 (55) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 (84) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 (54) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:05:37 GMT (35) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 7: Server: CSCO/7 (14) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 8: Contact: (51) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: Header 10: (0) [Feb 6 14:05:37] VERBOSE[28216] logger.c: --- (10 headers 0 lines) --- [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: = Found Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag Our tag: as7b4ff713 [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '322c33f5339516b169f66f393394e38a@66.114.80.26' Request 102: Found [Feb 6 14:05:37] DEBUG[28216] chan_sip.c: SIP response 180 to standard invite [Feb 6 14:05:37] DEBUG[28216] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081acce8 [Feb 6 14:05:37] VERBOSE[28240] logger.c: -- SIP/12128121207010001-081acce8 is ringing [Feb 6 14:05:37] VERBOSE[28240] 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=z9hG4bK19c6bced325A844A;received=66.114.80.25 From: "poly work" ;tag=F6081CF0-EA08F053 To: ;tag=as5f04973c Call-ID: 24d196bc-42090316-ebcda139@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 <------------> [Feb 6 14:05:37] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:05:37] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:05:37] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 6 (Ringing) [Feb 6 14:05:38] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1028 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport From: "poly work" ;tag=as7b4ff713 To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Date: Tue, 06 Feb 2007 19:05:39 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 142 v=0 o=Cisco-SIPUA 26135 8009 IN IP4 192.168.0.217 s=SIP Call c=IN IP4 192.168.0.217 t=0 0 m=audio 18228 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK1504de2e;rport (63) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=as7b4ff713 (55) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 (84) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 (54) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:05:39 GMT (35) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 7: Server: CSCO/7 (14) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 8: Contact: (51) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 9: Content-Type: application/sdp (29) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 10: Content-Length: 142 (19) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 11: (0) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Line: o=Cisco-SIPUA 26135 8009 IN IP4 192.168.0.217 (45) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Line: s=SIP Call (10) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Line: c=IN IP4 192.168.0.217 (22) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Line: m=audio 18228 RTP/AVP 0 (23) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:05:38] VERBOSE[28216] logger.c: --- (11 headers 7 lines) --- [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: = Found Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag 003094c44b8900cf7d38238a-78a5d3f8 Our tag: as7b4ff713 [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Acked pending invite 102 [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Stopping retransmission on '322c33f5339516b169f66f393394e38a@66.114.80.26' of Request 102: Match Not Found [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: SIP response 200 to standard invite [Feb 6 14:05:38] VERBOSE[28216] logger.c: Found RTP audio format 0 [Feb 6 14:05:38] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.217:18228 [Feb 6 14:05:38] VERBOSE[28216] logger.c: Found description format PCMU for ID 0 [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: T38 state changed to 0 on channel SIP/12128121207010001-081acce8 [Feb 6 14:05:38] VERBOSE[28216] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Feb 6 14:05:38] VERBOSE[28216] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Feb 6 14:05:38] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.217:18228 [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: We have an owner, now see if we need to change this call [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Updating call counter for outgoing call [Feb 6 14:05:38] DEBUG[28216] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001 [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: build_route: Contact hop: [Feb 6 14:05:38] VERBOSE[28216] logger.c: list_route: hop: [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Strict routing enforced for session 322c33f5339516b169f66f393394e38a@66.114.80.26 [Feb 6 14:05:38] VERBOSE[28216] logger.c: set_destination: Parsing for address/port to send to [Feb 6 14:05:38] VERBOSE[28216] logger.c: set_destination: set destination to 192.168.0.217, port 5060 [Feb 6 14:05:38] VERBOSE[28216] logger.c: Transmitting (NAT) to 66.114.80.25:1028: ACK sip:12128121207010001@192.168.0.217:5060 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK048d5ceb;rport From: "poly work" ;tag=as7b4ff713 To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 Contact: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 CSeq: 102 ACK User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [Feb 6 14:05:38] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:05:38] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:05:38] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [Feb 6 14:05:38] DEBUG[28240] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081acce8 [Feb 6 14:05:38] VERBOSE[28240] logger.c: -- SIP/12128121207010001-081acce8 answered SIP/xyz011101-081ae8a8 [Feb 6 14:05:38] DEBUG[28240] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081ae8a8 [Feb 6 14:05:38] DEBUG[28240] chan_sip.c: SIP answering channel: SIP/xyz011101-081ae8a8 [Feb 6 14:05:38] DEBUG[28240] chan_sip.c: Setting framing from config on incoming call [Feb 6 14:05:38] DEBUG[28240] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 6 14:05:38] DEBUG[28240] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Feb 6 14:05:38] VERBOSE[28240] logger.c: Audio is at 66.114.80.26 port 49844 [Feb 6 14:05:38] VERBOSE[28240] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 6 14:05:38] VERBOSE[28240] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 6 14:05:38] DEBUG[28240] chan_sip.c: -- Done with adding codecs to SDP [Feb 6 14:05:38] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:38] DEBUG[28240] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 6 14:05:38] VERBOSE[28240] 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=z9hG4bK19c6bced325A844A;received=66.114.80.25 From: "poly work" ;tag=F6081CF0-EA08F053 To: ;tag=as5f04973c Call-ID: 24d196bc-42090316-ebcda139@192.168.0.250 CSeq: 2 INVITE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 213 v=0 o=root 28240 28240 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 49844 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Feb 6 14:05:38] DEBUG[28240] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #77 [Feb 6 14:05:38] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:05:38] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:05:38] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [Feb 6 14:05:38] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Feb 6 14:05:38] DEBUG[28205] chan_sip.c: Checking device state for peer xyz011101 [Feb 6 14:05:38] DEBUG[28205] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Feb 6 14:05:38] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1025 ---> ACK sip:100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK7edfbb7e317353BB From: "poly work" ;tag=F6081CF0-EA08F053 To: ;tag=as5f04973c CSeq: 2 ACK Call-ID: 24d196bc-42090316-ebcda139@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="1bf09b1c", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="0caa5841ebda431fcf3f2fd74eed3bfa", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 0: ACK sip:100@66.114.80.26 SIP/2.0 (32) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK7edfbb7e317353BB (61) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=F6081CF0-EA08F053 (75) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=as5f04973c (59) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 4: CSeq: 2 ACK (11) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 24d196bc-42090316-ebcda139@192.168.0.250 (49) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 9: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="1bf09b1c", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="0caa5841ebda431fcf3f2fd74eed3bfa", algorithm=MD5 (197) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 10: Max-Forwards: 70 (16) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 11: Content-Length: 0 (17) [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Header 12: (0) [Feb 6 14:05:38] VERBOSE[28216] logger.c: --- (12 headers 0 lines) --- [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: = No match Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag 003094c44b8900cf7d38238a-78a5d3f8 Our tag: as7b4ff713 [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: = Found Their Call ID: 24d196bc-42090316-ebcda139@192.168.0.250 Their Tag F6081CF0-EA08F053 Our tag: as5f04973c [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #77 [Feb 6 14:05:38] DEBUG[28216] chan_sip.c: Stopping retransmission on '24d196bc-42090316-ebcda139@192.168.0.250' of Response 2: Match Not Found [Feb 6 14:05:38] DEBUG[28240] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:18228 [Feb 6 14:05:38] DEBUG[28240] channel.c: Building translator from ulaw to SLINEAR for spies on channel SIP/xyz011101-081ae8a8 [Feb 6 14:05:38] DEBUG[28240] rtp.c: Ooh, format changed from unknown to ulaw [Feb 6 14:05:38] DEBUG[28240] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Feb 6 14:05:38] DEBUG[28240] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2262 [Feb 6 14:05:38] DEBUG[28240] channel.c: Building translator from ulaw to SLINEAR for spies on channel SIP/xyz011101-081ae8a8 [Feb 6 14:05:38] DEBUG[28240] rtp.c: Ooh, format changed from unknown to ulaw [Feb 6 14:05:38] DEBUG[28240] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Feb 6 14:05:41] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1028 ---> INVITE sip:111@66.114.80.26:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK78f7a65d From: ;tag=003094c44b8900cf7d38238a-78a5d3f8 To: "poly work" ;tag=as7b4ff713 Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Date: Tue, 06 Feb 2007 19:05:41 GMT CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 136 v=0 o=Cisco-SIPUA 20766 5670 IN IP4 192.168.0.217 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 18228 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 0: INVITE sip:111@66.114.80.26:5060 SIP/2.0 (40) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK78f7a65d (58) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 2: From: ;tag=003094c44b8900cf7d38238a-78a5d3f8 (86) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 3: To: "poly work" ;tag=as7b4ff713 (53) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 (54) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:05:41 GMT (35) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 6: CSeq: 101 INVITE (16) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 8: Contact: (51) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 9: Content-Type: application/sdp (29) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 10: Content-Length: 136 (19) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 11: (0) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Line: o=Cisco-SIPUA 20766 5670 IN IP4 192.168.0.217 (45) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Line: s=SIP Call (10) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Line: c=IN IP4 0.0.0.0 (16) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Line: m=audio 18228 RTP/AVP 0 (23) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:05:41] VERBOSE[28216] logger.c: --- (11 headers 7 lines) --- [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: = Found Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag 003094c44b8900cf7d38238a-78a5d3f8 Our tag: as7b4ff713 [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 6 14:05:41] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1028 (NAT) [Feb 6 14:05:41] VERBOSE[28216] logger.c: Found RTP audio format 0 [Feb 6 14:05:41] VERBOSE[28216] logger.c: Peer audio RTP is at port 0.0.0.0:18228 [Feb 6 14:05:41] VERBOSE[28216] logger.c: Found description format PCMU for ID 0 [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: T38 state changed to 0 on channel SIP/12128121207010001-081acce8 [Feb 6 14:05:41] VERBOSE[28216] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Feb 6 14:05:41] VERBOSE[28216] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Feb 6 14:05:41] VERBOSE[28216] logger.c: Peer audio RTP is at port 0.0.0.0:18228 [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: We have an owner, now see if we need to change this call [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Got a SIP re-invite for call 322c33f5339516b169f66f393394e38a@66.114.80.26 [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: SIP/12128121207010001-081acce8: This call is UP.... [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Setting framing from config on incoming call [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Feb 6 14:05:41] VERBOSE[28216] logger.c: Audio is at 66.114.80.26 port 40280 [Feb 6 14:05:41] VERBOSE[28216] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: -- Done with adding codecs to SDP [Feb 6 14:05:41] DEBUG[28216] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 6 14:05:41] VERBOSE[28216] logger.c: <--- Reliably Transmitting (NAT) to 66.114.80.25:1028 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK78f7a65d;received=66.114.80.25 From: ;tag=003094c44b8900cf7d38238a-78a5d3f8 To: "poly work" ;tag=as7b4ff713 Call-ID: 322c33f5339516b169f66f393394e38a@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: 157 v=0 o=root 28240 28241 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 40280 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv <------------> [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #80 [Feb 6 14:05:41] DEBUG[28240] channel.c: Set channel SIP/xyz011101-081ae8a8 to write format slin [Feb 6 14:05:41] VERBOSE[28240] logger.c: -- Started music on hold, class 'xyz', on channel 'SIP/xyz011101-081ae8a8' [Feb 6 14:05:41] DEBUG[28240] channel.c: Scheduling timer at 160 sample intervals [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] rtp.c: Difference is 888, ms is 131 [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1028 ---> ACK sip:111@66.114.80.26:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK0433237b From: ;tag=003094c44b8900cf7d38238a-78a5d3f8 To: "poly work" ;tag=as7b4ff713 Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Date: Tue, 06 Feb 2007 19:05:42 GMT CSeq: 101 ACK User-Agent: CSCO/7 Content-Length: 0 <-------------> [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 0: ACK sip:111@66.114.80.26:5060 SIP/2.0 (37) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK0433237b (58) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 2: From: ;tag=003094c44b8900cf7d38238a-78a5d3f8 (86) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 3: To: "poly work" ;tag=as7b4ff713 (53) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 (54) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:05:42 GMT (35) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 6: CSeq: 101 ACK (13) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 8: Content-Length: 0 (17) [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Header 9: (0) [Feb 6 14:05:41] VERBOSE[28216] logger.c: --- (9 headers 0 lines) --- [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: = Found Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag 003094c44b8900cf7d38238a-78a5d3f8 Our tag: as7b4ff713 [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #80 [Feb 6 14:05:41] DEBUG[28216] chan_sip.c: Stopping retransmission on '322c33f5339516b169f66f393394e38a@66.114.80.26' of Response 101: Match Not Found [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:41] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] DEBUG[28240] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:05:42] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1025 ---> BYE sip:100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKb4e1cb581A575655 From: "poly work" ;tag=F6081CF0-EA08F053 To: ;tag=as5f04973c CSeq: 3 BYE Call-ID: 24d196bc-42090316-ebcda139@192.168.0.250 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="1bf09b1c", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="1a3d8965549947a8277d190d06fd6a73", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 0: BYE sip:100@66.114.80.26 SIP/2.0 (32) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKb4e1cb581A575655 (61) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=F6081CF0-EA08F053 (75) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=as5f04973c (59) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 4: CSeq: 3 BYE (11) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 24d196bc-42090316-ebcda139@192.168.0.250 (49) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 8: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="1bf09b1c", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="1a3d8965549947a8277d190d06fd6a73", algorithm=MD5 (197) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Header 11: (0) [Feb 6 14:05:42] VERBOSE[28216] logger.c: --- (11 headers 0 lines) --- [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: = No match Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag 003094c44b8900cf7d38238a-78a5d3f8 Our tag: as7b4ff713 [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: = Found Their Call ID: 24d196bc-42090316-ebcda139@192.168.0.250 Their Tag F6081CF0-EA08F053 Our tag: as5f04973c [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Feb 6 14:05:42] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Setting SIP_ALREADYGONE on dialog 24d196bc-42090316-ebcda139@192.168.0.250 [Feb 6 14:05:42] DEBUG[28216] chan_sip.c: Received bye, issuing owner hangup [Feb 6 14:05:42] VERBOSE[28216] 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=z9hG4bKb4e1cb581A575655;received=66.114.80.25 From: "poly work" ;tag=F6081CF0-EA08F053 To: ;tag=as5f04973c Call-ID: 24d196bc-42090316-ebcda139@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 <------------> [Feb 6 14:05:42] DEBUG[28240] channel.c: Set channel SIP/xyz011101-081ae8a8 to write format ulaw [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Stopped music on hold on SIP/xyz011101-081ae8a8 [Feb 6 14:05:42] DEBUG[28240] channel.c: Scheduling timer at 0 sample intervals [Feb 6 14:05:42] DEBUG[28240] channel.c: Didn't get a frame from channel: SIP/xyz011101-081ae8a8 [Feb 6 14:05:42] DEBUG[28240] channel.c: Bridge stops bridging channels SIP/xyz011101-081ae8a8 and SIP/12128121207010001-081acce8 [Feb 6 14:05:42] DEBUG[28240] channel.c: Hanging up channel 'SIP/12128121207010001-081acce8' [Feb 6 14:05:42] DEBUG[28240] chan_sip.c: Hangup call SIP/12128121207010001-081acce8, SIP callid 322c33f5339516b169f66f393394e38a@66.114.80.26) [Feb 6 14:05:42] DEBUG[28240] chan_sip.c: update_call_counter(12128121207010001) - decrement call limit counter on hangup [Feb 6 14:05:42] DEBUG[28240] chan_sip.c: Updating call counter for incoming call [Feb 6 14:05:42] DEBUG[28240] chan_sip.c: Call from user '12128121207010001' removed from call limit 3 [Feb 6 14:05:42] VERBOSE[28240] logger.c: Scheduling destruction of SIP dialog '322c33f5339516b169f66f393394e38a@66.114.80.26' in 32000 ms (Method: ACK) [Feb 6 14:05:42] DEBUG[28240] chan_sip.c: Strict routing enforced for session 322c33f5339516b169f66f393394e38a@66.114.80.26 [Feb 6 14:05:42] VERBOSE[28240] logger.c: set_destination: Parsing for address/port to send to [Feb 6 14:05:42] VERBOSE[28240] logger.c: set_destination: set destination to 192.168.0.217, port 5060 [Feb 6 14:05:42] VERBOSE[28240] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1028: BYE sip:12128121207010001@192.168.0.217:5060 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK3f3cd170;rport From: "poly work" ;tag=as7b4ff713 To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 CSeq: 103 BYE User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [Feb 6 14:05:42] DEBUG[28240] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #82 [Feb 6 14:05:42] DEBUG[28240] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081acce8 [Feb 6 14:05:42] DEBUG[28240] rtp.c: Channel '' has no RTP, not doing anything [Feb 6 14:05:42] DEBUG[28240] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Feb 6 14:05:42] DEBUG[28240] res_agi.c: SIP/xyz011101-081ae8a8 hungup [Feb 6 14:05:42] DEBUG[28240] pbx.c: Spawn extension (xyz,100,3) exited non-zero on 'SIP/xyz011101-081ae8a8' [Feb 6 14:05:42] VERBOSE[28240] logger.c: == Spawn extension (xyz, 100, 3) exited non-zero on 'SIP/xyz011101-081ae8a8' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Macro' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [h@xyz:1] Macro("SIP/xyz011101-081ae8a8", "logvar|AGISTATUS") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Function result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Expression result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'GotoIf' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081ae8a8", "1?+1:+2") in new stack [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Log' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081ae8a8", "NOTICE|"[28241]: 1170788735.2: AGISTATUS=HANGUP"") in new stack [Feb 6 14:05:42] NOTICE[28240] Ext. s: "[28241]: 1170788735.2: AGISTATUS=HANGUP" [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'NoOp' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081ae8a8", "") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Macro' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [h@xyz:2] Macro("SIP/xyz011101-081ae8a8", "logvar|DIALSTATUS") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Function result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Expression result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'GotoIf' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081ae8a8", "1?+1:+2") in new stack [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Log' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081ae8a8", "NOTICE|"[28241]: 1170788735.2: DIALSTATUS=ANSWER"") in new stack [Feb 6 14:05:42] NOTICE[28240] Ext. s: "[28241]: 1170788735.2: DIALSTATUS=ANSWER" [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'NoOp' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081ae8a8", "") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Macro' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [h@xyz:3] Macro("SIP/xyz011101-081ae8a8", "logvar|ANSWEREDTIME") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Function result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Expression result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'GotoIf' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081ae8a8", "1?+1:+2") in new stack [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Log' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081ae8a8", "NOTICE|"[28241]: 1170788735.2: ANSWEREDTIME=4"") in new stack [Feb 6 14:05:42] NOTICE[28240] Ext. s: "[28241]: 1170788735.2: ANSWEREDTIME=4" [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'NoOp' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081ae8a8", "") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Macro' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [h@xyz:4] Macro("SIP/xyz011101-081ae8a8", "logvar|RTPAUDIOQOS") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Function result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Expression result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'GotoIf' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081ae8a8", "1?+1:+2") in new stack [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Log' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081ae8a8", "NOTICE|"[28241]: 1170788735.2: RTPAUDIOQOS=ssrc=1179805111;themssrc=60637185;lp=0;rxjitter=0.001780;rxcount=181;txjitter=0.000000;txcount=180;rlp=0;rtt=0.000000"") in new stack [Feb 6 14:05:42] NOTICE[28240] Ext. s: "[28241]: 1170788735.2: RTPAUDIOQOS=ssrc=1179805111;themssrc=60637185;lp=0;rxjitter=0.001780;rxcount=181;txjitter=0.000000;txcount=180;rlp=0;rtt=0.000000" [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'NoOp' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081ae8a8", "") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Macro' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [h@xyz:5] Macro("SIP/xyz011101-081ae8a8", "logvar|UNIQUEID") in new stack [Feb 6 14:05:42] DEBUG[28240] pbx.c: Function result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Expression result is '1' [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'GotoIf' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081ae8a8", "1?+1:+2") in new stack [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'Log' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081ae8a8", "NOTICE|"[28241]: 1170788735.2: UNIQUEID=1170788735.2"") in new stack [Feb 6 14:05:42] NOTICE[28240] Ext. s: "[28241]: 1170788735.2: UNIQUEID=1170788735.2" [Feb 6 14:05:42] DEBUG[28240] pbx.c: Launching 'NoOp' [Feb 6 14:05:42] VERBOSE[28240] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081ae8a8", "") in new stack [Feb 6 14:05:42] DEBUG[28240] channel.c: Spy MixMonitor removed from channel SIP/xyz011101-081ae8a8 [Feb 6 14:05:42] DEBUG[28240] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [Feb 6 14:05:42] DEBUG[28240] 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-02-06 14:05:35','"poly work" <111>','111','h','xyz', 'SIP/xyz011101-081ae8a8','SIP/12128121207010001-081acce8','NoOp','',7,4,'ANSWERED',3,'','1170788735.2','2:xyz011101>100') [Feb 6 14:05:42] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1028 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK3f3cd170;rport From: "poly work" ;tag=as7b4ff713 To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Date: Tue, 06 Feb 2007 19:05:43 GMT CSeq: 103 BYE Server: CSCO/7 Content-Length: 0 <-------------> [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK3f3cd170;rport (63) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=as7b4ff713 (55) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=003094c44b8900cf7d38238a-78a5d3f8 (84) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 (54) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:05:43 GMT (35) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 6: CSeq: 103 BYE (13) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 7: Server: CSCO/7 (14) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 8: Content-Length: 0 (17) [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Header 9: (0) [Feb 6 14:05:43] VERBOSE[28216] logger.c: --- (9 headers 0 lines) --- [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: = Found Their Call ID: 322c33f5339516b169f66f393394e38a@66.114.80.26 Their Tag 003094c44b8900cf7d38238a-78a5d3f8 Our tag: as7b4ff713 [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #82 [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Stopping retransmission on '322c33f5339516b169f66f393394e38a@66.114.80.26' of Request 103: Match Not Found [Feb 6 14:05:43] VERBOSE[28216] logger.c: SIP Response message for INCOMING dialog BYE arrived [Feb 6 14:05:43] VERBOSE[28216] logger.c: Really destroying SIP dialog '322c33f5339516b169f66f393394e38a@66.114.80.26' Method: ACK [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Updating call counter for incoming call [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: Call from user '12128121207010001' removed from call limit 3 [Feb 6 14:05:43] DEBUG[28216] chan_sip.c: This call did not properly clean up call limits. Call ID 322c33f5339516b169f66f393394e38a@66.114.80.26 [Feb 6 14:05:42] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:05:43] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:05:43] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [Feb 6 14:05:42] VERBOSE[28243] logger.c: == End MixMonitor Recording SIP/xyz011101-081ae8a8 [Feb 6 14:05:43] VERBOSE[28243] logger.c: == Executing [/var/lib/asterisk/agi-bin/_UTILS/MixMonitor.sh /var/spool/asterisk/monitor/02062007-140535-111-100.WAV /var/spool/asterisk/recordings/xyz/02062007-140535-111-100.WAV &] [Feb 6 14:05:43] DEBUG[28240] channel.c: Hanging up channel 'SIP/xyz011101-081ae8a8' [Feb 6 14:05:43] DEBUG[28240] chan_sip.c: Hangup call SIP/xyz011101-081ae8a8, SIP callid 24d196bc-42090316-ebcda139@192.168.0.250) [Feb 6 14:05:43] DEBUG[28240] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup [Feb 6 14:05:43] DEBUG[28240] chan_sip.c: Updating call counter for incoming call [Feb 6 14:05:43] DEBUG[28240] chan_sip.c: Call from user 'xyz011101' removed from call limit 3 [Feb 6 14:05:43] DEBUG[28240] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081ae8a8 [Feb 6 14:05:43] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Feb 6 14:05:43] DEBUG[28205] chan_sip.c: Checking device state for peer xyz011101 [Feb 6 14:05:43] DEBUG[28205] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Feb 6 14:05:44] VERBOSE[28216] logger.c: Really destroying SIP dialog '24d196bc-42090316-ebcda139@192.168.0.250' Method: BYE