<--- 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=z9hG4bK1005e9de4A58D61B From: "poly work" ;tag=292799EC-1A35C8CF To: CSeq: 1 INVITE Call-ID: aa5821b8-cf222712-838000b5@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=- 1170734506 1170734506 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2260 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:04:52] DEBUG[28216] chan_sip.c: Header 0: INVITE sip:100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (58) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK1005e9de4A58D61B (61) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=292799EC-1A35C8CF (75) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 3: To: (44) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 4: CSeq: 1 INVITE (14) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 5: Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 (49) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 11: Max-Forwards: 70 (16) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 13: Content-Length: 251 (19) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 14: (0) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: o=- 1170734506 1170734506 IN IP4 192.168.0.250 (46) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: s=Polycom IP Phone (18) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=sendrecv (10) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: m=audio 2260 RTP/AVP 0 8 18 101 (31) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 14:04:52] VERBOSE[28216] logger.c: --- (14 headers 11 lines) --- [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: = No match Their Call ID: 350b2e7e-530e7e58-d45966bb@192.168.0.250 Their Tag AD339BB2-D4D6A955 Our tag: as22ff6df3 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: = No match Their Call ID: c1857439-c6a0353-d20f7616@192.168.0.250 Their Tag A3010FED-E54FCFF0 Our tag: as1695c06c [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: = No match Their Call ID: 003094c4-4b890004-43a68a92-631d873f@192.168.0.217 Their Tag Our tag: as0417a43e [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: = No match Their Call ID: 079a4aa771926a077ca0260c255137c5@66.114.80.26 Their Tag bb62d7e482cc1e58bd69683900d56829.5a6b Our tag: as14727978 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Allocating new SIP dialog for aa5821b8-cf222712-838000b5@192.168.0.250 - INVITE (With RTP) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Found SIP option: -100rel- [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Matched SIP option: 100rel [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Found SIP option: -replaces- [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Matched SIP option: replaces [Feb 6 14:04:52] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Feb 6 14:04:52] VERBOSE[28216] logger.c: Using INVITE request as basis request - aa5821b8-cf222712-838000b5@192.168.0.250 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:04:52] 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=z9hG4bK1005e9de4A58D61B;received=66.114.80.25 From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as128778d0 Call-ID: aa5821b8-cf222712-838000b5@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="249ace0b" Content-Length: 0 <------------> [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #59 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Scheduling destruction of SIP dialog 'aa5821b8-cf222712-838000b5@192.168.0.250' in 32000 ms (Method: INVITE) [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found user 'xyz011101' [Feb 6 14:04:52] 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=z9hG4bK1005e9de4A58D61B From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as128778d0 CSeq: 1 ACK Call-ID: aa5821b8-cf222712-838000b5@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:04:52] DEBUG[28216] chan_sip.c: Header 0: ACK sip:100@pbxtest.acecape.com:5060 SIP/2.0 (44) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK1005e9de4A58D61B (61) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=292799EC-1A35C8CF (75) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=as128778d0 (59) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 4: CSeq: 1 ACK (11) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 5: Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 (49) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 11: (0) [Feb 6 14:04:52] VERBOSE[28216] logger.c: --- (11 headers 0 lines) --- [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: = Found Their Call ID: aa5821b8-cf222712-838000b5@192.168.0.250 Their Tag 292799EC-1A35C8CF Our tag: as128778d0 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #59 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Stopping retransmission on 'aa5821b8-cf222712-838000b5@192.168.0.250' of Response 1: Match Not Found [Feb 6 14:04:52] 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=z9hG4bK91a9ce698A841A46 From: "poly work" ;tag=292799EC-1A35C8CF To: CSeq: 2 INVITE Call-ID: aa5821b8-cf222712-838000b5@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="249ace0b", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="fb147e350e16d5c5c690b3924b632c0a", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1170734506 1170734506 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 a=sendrecv m=audio 2260 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:04:52] DEBUG[28216] chan_sip.c: Header 0: INVITE sip:100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (58) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK91a9ce698A841A46 (61) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=292799EC-1A35C8CF (75) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 3: To: (44) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 4: CSeq: 2 INVITE (14) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 5: Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 (49) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="249ace0b", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="fb147e350e16d5c5c690b3924b632c0a", algorithm=MD5 (197) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 12: Max-Forwards: 70 (16) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 14: Content-Length: 251 (19) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Header 15: (0) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: o=- 1170734506 1170734506 IN IP4 192.168.0.250 (46) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: s=Polycom IP Phone (18) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=sendrecv (10) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: m=audio 2260 RTP/AVP 0 8 18 101 (31) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 14:04:52] VERBOSE[28216] logger.c: --- (15 headers 11 lines) --- [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: = Found Their Call ID: aa5821b8-cf222712-838000b5@192.168.0.250 Their Tag 292799EC-1A35C8CF Our tag: as128778d0 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 6 14:04:52] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Feb 6 14:04:52] VERBOSE[28216] logger.c: Using INVITE request as basis request - aa5821b8-cf222712-838000b5@192.168.0.250 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found user 'xyz011101' [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found RTP audio format 0 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found RTP audio format 8 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found RTP audio format 18 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found RTP audio format 101 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.250:2260 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found description format PCMU for ID 0 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found description format PCMA for ID 8 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found description format G729 for ID 18 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Found description format telephone-event for ID 101 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: T38 state changed to 0 on channel [Feb 6 14:04:52] VERBOSE[28216] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Feb 6 14:04:52] VERBOSE[28216] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 6 14:04:52] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.250:2260 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Checking SIP call limits for device xyz011101 [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Updating call counter for incoming call [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: Call from user 'xyz011101' is 1 out of 3 [Feb 6 14:04:52] VERBOSE[28216] logger.c: Looking for 100 in xyz (domain pbxtest.acecape.com) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: This channel will not be able to handle video. [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: build_route: Contact hop: [Feb 6 14:04:52] VERBOSE[28216] logger.c: list_route: hop: [Feb 6 14:04:52] DEBUG[28216] chan_sip.c: SIP/xyz011101-081c3808: New call is still down.... Trying... [Feb 6 14:04:52] 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=z9hG4bK91a9ce698A841A46;received=66.114.80.25 From: "poly work" ;tag=292799EC-1A35C8CF To: Call-ID: aa5821b8-cf222712-838000b5@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:04:52] DEBUG[28216] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c3808 [Feb 6 14:04:52] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Feb 6 14:04:52] DEBUG[28205] chan_sip.c: Checking device state for peer xyz011101 [Feb 6 14:04:52] DEBUG[28205] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Feb 6 14:04:52] DEBUG[28222] pbx.c: Launching 'Set' [Feb 6 14:04:52] VERBOSE[28222] logger.c: -- Executing [100@xyz:1] Set("SIP/xyz011101-081c3808", "TIMEOUT(absolute)=10800") in new stack [Feb 6 14:04:52] VERBOSE[28222] logger.c: -- Channel will hangup at 2007-02-06 22:04:52 UTC. [Feb 6 14:04:52] DEBUG[28222] pbx.c: Function result is '0' [Feb 6 14:04:52] DEBUG[28222] pbx.c: Launching 'NoOp' [Feb 6 14:04:52] VERBOSE[28222] logger.c: -- Executing [100@xyz:2] NoOp("SIP/xyz011101-081c3808", "0") in new stack [Feb 6 14:04:52] DEBUG[28222] pbx.c: Launching 'AGI' [Feb 6 14:04:52] VERBOSE[28222] logger.c: -- Executing [100@xyz:3] AGI("SIP/xyz011101-081c3808", "callprocessing.agi") in new stack [Feb 6 14:04:52] VERBOSE[28222] logger.c: -- Launched AGI Script /usr/local/asterisk/var/lib/asterisk/agi-bin/callprocessing.agi [Feb 6 14:04:53] DEBUG[28222] pbx.c: Function result is 'xyz011101' [Feb 6 14:04:53] VERBOSE[28222] logger.c: -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=2:xyz011101>100) [Feb 6 14:04:54] VERBOSE[28222] logger.c: -- AGI Script Executing Application: (Set) Options: (CALLERID(name)=poly work|CALLERID(num)=111) [Feb 6 14:04:54] VERBOSE[28222] logger.c: -- AGI Script Executing Application: (MixMonitor) Options: (/var/spool/asterisk/monitor/02062007-140453-111-100.WAV|bW(+1)|/var/lib/asterisk/agi-bin/_UTILS/MixMonitor.sh /var/spool/asterisk/monitor/02062007-140453-111-100.WAV /var/spool/asterisk/recordings/xyz/02062007-140453-111-100.WAV &) [Feb 6 14:04:54] DEBUG[28222] channel.c: Spy MixMonitor added to channel SIP/xyz011101-081c3808 [Feb 6 14:04:54] VERBOSE[28225] logger.c: == Begin MixMonitor Recording SIP/xyz011101-081c3808 [Feb 6 14:04:54] VERBOSE[28222] logger.c: -- AGI Script Executing Application: (Dial) Options: (SIP/12128121207010001|180|) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Setting NAT on RTP to On [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: This channel will not be able to handle video. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable MIXMONITOR_FILENAME. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable CP_PID. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable STACK-xyz-100-3. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable STACK-xyz-100-2. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable STACK-xyz-100-1. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable SIPCALLID. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable SIPUSERAGENT. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable SIPDOMAIN. [Feb 6 14:04:54] DEBUG[28222] channel.c: Not copying variable SIPURI. [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Outgoing Call for 12128121207010001 [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Updating call counter for outgoing call [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Call to peer '12128121207010001' is 1 out of 3 [Feb 6 14:04:54] DEBUG[28222] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001 [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Feb 6 14:04:54] VERBOSE[28222] logger.c: Audio is at 66.114.80.26 port 41232 [Feb 6 14:04:54] VERBOSE[28222] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: -- Done with adding codecs to SDP [Feb 6 14:04:54] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 0: INVITE sip:12128121207010001@192.168.0.217:5060 SIP/2.0 (55) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK6ab922fd;rport (63) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 2: From: "poly work" ;tag=as5095192c (55) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 3: To: (46) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 4: Contact: (31) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 5: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 (54) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 7: User-Agent: AcePBX (18) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 9: Date: Tue, 06 Feb 2007 19:04:54 GMT (35) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 11: Supported: replaces (19) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 12: Content-Type: application/sdp (29) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 13: Content-Length: 157 (19) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Header 14: (0) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: v=0 (3) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: o=root 28222 28222 IN IP4 66.114.80.26 (38) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: s=session (9) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: c=IN IP4 66.114.80.26 (21) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: m=audio 41232 RTP/AVP 0 (23) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: a=ptime:20 (10) [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: Line: a=sendrecv (10) [Feb 6 14:04:54] VERBOSE[28222] 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=z9hG4bK6ab922fd;rport From: "poly work" ;tag=as5095192c To: Contact: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 CSeq: 102 INVITE User-Agent: AcePBX Max-Forwards: 70 Date: Tue, 06 Feb 2007 19:04:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 157 v=0 o=root 28222 28222 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 41232 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv --- [Feb 6 14:04:54] DEBUG[28222] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #61 [Feb 6 14:04:54] VERBOSE[28222] logger.c: -- Called 12128121207010001 [Feb 6 14:04:54] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:04:54] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:04:54] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 6 (Ringing) [Feb 6 14:04:54] 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=z9hG4bK6ab922fd;rport From: "poly work" ;tag=as5095192c To: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Date: Tue, 06 Feb 2007 19:04:55 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 <-------------> [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK6ab922fd;rport (63) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=as5095192c (55) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 3: To: (46) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 (54) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:04:55 GMT (35) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 7: Server: CSCO/7 (14) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 8: Contact: (51) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 10: (0) [Feb 6 14:04:54] VERBOSE[28216] logger.c: --- (10 headers 0 lines) --- [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: = Found Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag Our tag: as5095192c [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: *** SIP TIMER: Cancelling retransmission #61 - INVITE (got response) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1b057f796d2c8e583b918d911e00a8cd@66.114.80.26' Request 102: Found [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: SIP response 100 to standard invite [Feb 6 14:04:54] 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=z9hG4bK6ab922fd;rport From: "poly work" ;tag=as5095192c To: ;tag=003094c44b8900ce0eeecaa6-0988066f Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Date: Tue, 06 Feb 2007 19:04:55 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 <-------------> [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK6ab922fd;rport (63) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=as5095192c (55) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=003094c44b8900ce0eeecaa6-0988066f (84) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 (54) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:04:55 GMT (35) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 7: Server: CSCO/7 (14) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 8: Contact: (51) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: Header 10: (0) [Feb 6 14:04:54] VERBOSE[28216] logger.c: --- (10 headers 0 lines) --- [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: = Found Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag Our tag: as5095192c [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1b057f796d2c8e583b918d911e00a8cd@66.114.80.26' Request 102: Found [Feb 6 14:04:54] DEBUG[28216] chan_sip.c: SIP response 180 to standard invite [Feb 6 14:04:54] DEBUG[28216] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081c8d58 [Feb 6 14:04:54] VERBOSE[28222] logger.c: -- SIP/12128121207010001-081c8d58 is ringing [Feb 6 14:04:54] VERBOSE[28222] 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=z9hG4bK91a9ce698A841A46;received=66.114.80.25 From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as6b89a935 Call-ID: aa5821b8-cf222712-838000b5@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:04:54] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:04:54] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:04:54] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 6 (Ringing) [Feb 6 14:04:55] 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=z9hG4bK6ab922fd;rport From: "poly work" ;tag=as5095192c To: ;tag=003094c44b8900ce0eeecaa6-0988066f Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Date: Tue, 06 Feb 2007 19:04:56 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 143 v=0 o=Cisco-SIPUA 18599 15138 IN IP4 192.168.0.217 s=SIP Call c=IN IP4 192.168.0.217 t=0 0 m=audio 18226 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK6ab922fd;rport (63) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=as5095192c (55) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=003094c44b8900ce0eeecaa6-0988066f (84) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 (54) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:04:56 GMT (35) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 7: Server: CSCO/7 (14) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 8: Contact: (51) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 9: Content-Type: application/sdp (29) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 10: Content-Length: 143 (19) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 11: (0) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: o=Cisco-SIPUA 18599 15138 IN IP4 192.168.0.217 (46) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: s=SIP Call (10) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: c=IN IP4 192.168.0.217 (22) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: m=audio 18226 RTP/AVP 0 (23) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:04:55] VERBOSE[28216] logger.c: --- (11 headers 7 lines) --- [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: = Found Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag 003094c44b8900ce0eeecaa6-0988066f Our tag: as5095192c [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Acked pending invite 102 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Stopping retransmission on '1b057f796d2c8e583b918d911e00a8cd@66.114.80.26' of Request 102: Match Not Found [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: SIP response 200 to standard invite [Feb 6 14:04:55] VERBOSE[28216] logger.c: Found RTP audio format 0 [Feb 6 14:04:55] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.217:18226 [Feb 6 14:04:55] VERBOSE[28216] logger.c: Found description format PCMU for ID 0 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: T38 state changed to 0 on channel SIP/12128121207010001-081c8d58 [Feb 6 14:04:55] VERBOSE[28216] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Feb 6 14:04:55] VERBOSE[28216] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Feb 6 14:04:55] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.217:18226 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: We have an owner, now see if we need to change this call [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Updating call counter for outgoing call [Feb 6 14:04:55] DEBUG[28216] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: build_route: Contact hop: [Feb 6 14:04:55] VERBOSE[28216] logger.c: list_route: hop: [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Strict routing enforced for session 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 [Feb 6 14:04:55] VERBOSE[28216] logger.c: set_destination: Parsing for address/port to send to [Feb 6 14:04:55] VERBOSE[28216] logger.c: set_destination: set destination to 192.168.0.217, port 5060 [Feb 6 14:04:55] 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=z9hG4bK47b4331a;rport From: "poly work" ;tag=as5095192c To: ;tag=003094c44b8900ce0eeecaa6-0988066f Contact: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 CSeq: 102 ACK User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [Feb 6 14:04:55] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:04:55] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:04:55] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [Feb 6 14:04:55] DEBUG[28222] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081c8d58 [Feb 6 14:04:55] VERBOSE[28222] logger.c: -- SIP/12128121207010001-081c8d58 answered SIP/xyz011101-081c3808 [Feb 6 14:04:55] DEBUG[28222] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c3808 [Feb 6 14:04:55] DEBUG[28222] chan_sip.c: SIP answering channel: SIP/xyz011101-081c3808 [Feb 6 14:04:55] DEBUG[28222] chan_sip.c: Setting framing from config on incoming call [Feb 6 14:04:55] DEBUG[28222] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 6 14:04:55] DEBUG[28222] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Feb 6 14:04:55] VERBOSE[28222] logger.c: Audio is at 66.114.80.26 port 48312 [Feb 6 14:04:55] VERBOSE[28222] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 6 14:04:55] VERBOSE[28222] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 6 14:04:55] DEBUG[28222] chan_sip.c: -- Done with adding codecs to SDP [Feb 6 14:04:55] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:04:55] DEBUG[28222] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 6 14:04:55] VERBOSE[28222] 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=z9hG4bK91a9ce698A841A46;received=66.114.80.25 From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as6b89a935 Call-ID: aa5821b8-cf222712-838000b5@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 28222 28222 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 48312 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:04:55] DEBUG[28222] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #63 [Feb 6 14:04:55] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:04:55] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:04:55] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 2 (In use) [Feb 6 14:04:55] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Feb 6 14:04:55] DEBUG[28205] chan_sip.c: Checking device state for peer xyz011101 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Feb 6 14:04:55] VERBOSE[28216] logger.c: Scheduling destruction of SIP dialog '51969d3e376c491f54d6608c1002c84e@66.114.80.26' in 32000 ms (Method: NOTIFY) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 0: NOTIFY sip:xyz011101@192.168.0.250 SIP/2.0 (42) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK231fefd2;rport (63) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 2: From: "Unknown" ;tag=as258002f0 (57) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 3: To: (33) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 4: Contact: (35) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 51969d3e376c491f54d6608c1002c84e@66.114.80.26 (54) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 NOTIFY (16) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 7: User-Agent: AcePBX (18) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 9: Event: message-summary (22) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 10: Content-Type: application/simple-message-summary (48) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 11: Content-Length: 96 (18) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 12: (0) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: Messages-Waiting: yes (21) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: Message-Account: sip:12128121210@66.114.80.26 (45) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Line: Voice-Message: 1/0 (0/0) (24) [Feb 6 14:04:55] VERBOSE[28216] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1025: NOTIFY sip:xyz011101@192.168.0.250 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK231fefd2;rport From: "Unknown" ;tag=as258002f0 To: Contact: Call-ID: 51969d3e376c491f54d6608c1002c84e@66.114.80.26 CSeq: 102 NOTIFY User-Agent: AcePBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 96 Messages-Waiting: yes Message-Account: sip:12128121210@66.114.80.26 Voice-Message: 1/0 (0/0) --- [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #65 [Feb 6 14:04:55] DEBUG[28205] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Feb 6 14:04:55] 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=z9hG4bK8c68c37a797F9037 From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as6b89a935 CSeq: 2 ACK Call-ID: aa5821b8-cf222712-838000b5@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="249ace0b", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="fb147e350e16d5c5c690b3924b632c0a", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 0: ACK sip:100@66.114.80.26 SIP/2.0 (32) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK8c68c37a797F9037 (61) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=292799EC-1A35C8CF (75) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=as6b89a935 (59) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 4: CSeq: 2 ACK (11) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 5: Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 (49) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 9: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="249ace0b", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="fb147e350e16d5c5c690b3924b632c0a", algorithm=MD5 (197) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 10: Max-Forwards: 70 (16) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 11: Content-Length: 0 (17) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 12: (0) [Feb 6 14:04:55] VERBOSE[28216] logger.c: --- (12 headers 0 lines) --- [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: = No match Their Call ID: 51969d3e376c491f54d6608c1002c84e@66.114.80.26 Their Tag Our tag: as258002f0 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: = No match Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag 003094c44b8900ce0eeecaa6-0988066f Our tag: as5095192c [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: = Found Their Call ID: aa5821b8-cf222712-838000b5@192.168.0.250 Their Tag 292799EC-1A35C8CF Our tag: as6b89a935 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #63 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Stopping retransmission on 'aa5821b8-cf222712-838000b5@192.168.0.250' of Response 2: Match Not Found [Feb 6 14:04:55] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1025 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK231fefd2;rport From: "Unknown" ;tag=as258002f0 To: ;tag=30A8CBD1-7FE02C54 CSeq: 102 NOTIFY Call-ID: 51969d3e376c491f54d6608c1002c84e@66.114.80.26 Contact: Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Content-Length: 0 <-------------> [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK231fefd2;rport (63) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 2: From: "Unknown" ;tag=as258002f0 (57) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=30A8CBD1-7FE02C54 (55) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 4: CSeq: 102 NOTIFY (16) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 51969d3e376c491f54d6608c1002c84e@66.114.80.26 (54) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 7: Event: message-summary (22) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 9: Content-Length: 0 (17) [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Header 10: (0) [Feb 6 14:04:55] VERBOSE[28216] logger.c: --- (10 headers 0 lines) --- [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: = Found Their Call ID: 51969d3e376c491f54d6608c1002c84e@66.114.80.26 Their Tag Our tag: as258002f0 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #65 [Feb 6 14:04:55] DEBUG[28216] chan_sip.c: Stopping retransmission on '51969d3e376c491f54d6608c1002c84e@66.114.80.26' of Request 102: Match Not Found [Feb 6 14:04:55] VERBOSE[28216] logger.c: Really destroying SIP dialog '51969d3e376c491f54d6608c1002c84e@66.114.80.26' Method: NOTIFY [Feb 6 14:04:56] DEBUG[28222] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2260 [Feb 6 14:04:56] DEBUG[28222] channel.c: Building translator from ulaw to SLINEAR for spies on channel SIP/xyz011101-081c3808 [Feb 6 14:04:56] DEBUG[28222] rtp.c: Ooh, format changed from unknown to ulaw [Feb 6 14:04:56] DEBUG[28222] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Feb 6 14:04:56] DEBUG[28222] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:18226 [Feb 6 14:04:56] DEBUG[28222] channel.c: Building translator from ulaw to SLINEAR for spies on channel SIP/xyz011101-081c3808 [Feb 6 14:04:56] DEBUG[28222] rtp.c: Ooh, format changed from unknown to ulaw [Feb 6 14:04:56] DEBUG[28222] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Feb 6 14:04:57] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1025 ---> INVITE sip:100@66.114.80.26 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKd48d22ae61A664EB From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as6b89a935 CSeq: 3 INVITE Call-ID: aa5821b8-cf222712-838000b5@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="249ace0b", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="49d63098bead97ba4f25c3f6fa963576", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 201 v=0 o=- 1170734506 1170734507 IN IP4 192.168.0.250 s=Polycom IP Phone c=IN IP4 192.168.0.250 t=0 0 m=audio 2260 RTP/AVP 0 101 a=sendonly a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 0: INVITE sip:100@66.114.80.26 SIP/2.0 (35) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKd48d22ae61A664EB (61) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=292799EC-1A35C8CF (75) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=as6b89a935 (59) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 4: CSeq: 3 INVITE (14) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 5: Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 (49) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 9: Supported: 100rel,replaces (26) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="249ace0b", uri="sip:100@pbxtest.acecape.com:5060;user=phone", response="49d63098bead97ba4f25c3f6fa963576", algorithm=MD5 (197) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 12: Max-Forwards: 70 (16) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 14: Content-Length: 201 (19) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 15: (0) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: v=0 (3) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: o=- 1170734506 1170734507 IN IP4 192.168.0.250 (46) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: s=Polycom IP Phone (18) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: t=0 0 (5) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: m=audio 2260 RTP/AVP 0 101 (26) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: a=sendonly (10) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 14:04:57] VERBOSE[28216] logger.c: --- (15 headers 9 lines) --- [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: = No match Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag 003094c44b8900ce0eeecaa6-0988066f Our tag: as5095192c [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: = Found Their Call ID: aa5821b8-cf222712-838000b5@192.168.0.250 Their Tag 292799EC-1A35C8CF Our tag: as6b89a935 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 6 14:04:57] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1025 (NAT) [Feb 6 14:04:57] VERBOSE[28216] logger.c: Found RTP audio format 0 [Feb 6 14:04:57] VERBOSE[28216] logger.c: Found RTP audio format 101 [Feb 6 14:04:57] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.250:2260 [Feb 6 14:04:57] VERBOSE[28216] logger.c: Found description format PCMU for ID 0 [Feb 6 14:04:57] VERBOSE[28216] logger.c: Found description format telephone-event for ID 101 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: T38 state changed to 0 on channel SIP/xyz011101-081c3808 [Feb 6 14:04:57] VERBOSE[28216] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Feb 6 14:04:57] VERBOSE[28216] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 6 14:04:57] VERBOSE[28216] logger.c: Peer audio RTP is at port 192.168.0.250:2260 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: We have an owner, now see if we need to change this call [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Got a SIP re-invite for call aa5821b8-cf222712-838000b5@192.168.0.250 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: SIP/xyz011101-081c3808: This call is UP.... [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Setting framing from config on incoming call [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Feb 6 14:04:57] VERBOSE[28216] logger.c: Audio is at 66.114.80.26 port 48312 [Feb 6 14:04:57] VERBOSE[28216] logger.c: Adding codec 0x4 (ulaw) to SDP [Feb 6 14:04:57] VERBOSE[28216] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: -- Done with adding codecs to SDP [Feb 6 14:04:57] DEBUG[28216] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=23) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 6 14:04:57] VERBOSE[28216] 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=z9hG4bKd48d22ae61A664EB;received=66.114.80.25 From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as6b89a935 Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 CSeq: 3 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 28222 28223 IN IP4 66.114.80.26 s=session c=IN IP4 66.114.80.26 t=0 0 m=audio 48312 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=recvonly <------------> [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #68 [Feb 6 14:04:57] DEBUG[28222] channel.c: Set channel SIP/12128121207010001-081c8d58 to write format slin [Feb 6 14:04:57] VERBOSE[28222] logger.c: -- Started music on hold, class 'xyz', on channel 'SIP/12128121207010001-081c8d58' [Feb 6 14:04:57] DEBUG[28222] channel.c: Scheduling timer at 160 sample intervals [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] rtp.c: Difference is 688, ms is 106 [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Feb 6 14:04:57] VERBOSE[28216] logger.c: Scheduling destruction of SIP dialog '6cdd59264d9fedce621267464edc2cba@66.114.80.26' in 32000 ms (Method: NOTIFY) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 0: NOTIFY sip:12128121207010001@192.168.0.217:5060 SIP/2.0 (55) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK6f37c1d4;rport (63) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 2: From: "Unknown" ;tag=as228e7a21 (57) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 3: To: (46) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 4: Contact: (35) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 5: Call-ID: 6cdd59264d9fedce621267464edc2cba@66.114.80.26 (54) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 NOTIFY (16) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 7: User-Agent: AcePBX (18) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 9: Event: message-summary (22) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 10: Content-Type: application/simple-message-summary (48) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 11: Content-Length: 96 (18) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 12: (0) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: Messages-Waiting: yes (21) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: Message-Account: sip:12128121210@66.114.80.26 (45) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Line: Voice-Message: 2/2 (0/0) (24) [Feb 6 14:04:57] VERBOSE[28216] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1028: NOTIFY sip:12128121207010001@192.168.0.217:5060 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK6f37c1d4;rport From: "Unknown" ;tag=as228e7a21 To: Contact: Call-ID: 6cdd59264d9fedce621267464edc2cba@66.114.80.26 CSeq: 102 NOTIFY User-Agent: AcePBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 96 Messages-Waiting: yes Message-Account: sip:12128121210@66.114.80.26 Voice-Message: 2/2 (0/0) --- [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #70 [Feb 6 14:04:57] 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=z9hG4bK274346886FB7FB85 From: "poly work" ;tag=292799EC-1A35C8CF To: ;tag=as6b89a935 CSeq: 3 ACK Call-ID: aa5821b8-cf222712-838000b5@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:04:57] DEBUG[28216] chan_sip.c: Header 0: ACK sip:100@66.114.80.26 SIP/2.0 (32) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK274346886FB7FB85 (61) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 2: From: "poly work" ;tag=292799EC-1A35C8CF (75) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 3: To: ;tag=as6b89a935 (59) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 4: CSeq: 3 ACK (11) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 5: Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 (49) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 9: Max-Forwards: 70 (16) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 10: Content-Length: 0 (17) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 11: (0) [Feb 6 14:04:57] VERBOSE[28216] logger.c: --- (11 headers 0 lines) --- [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: = No match Their Call ID: 6cdd59264d9fedce621267464edc2cba@66.114.80.26 Their Tag Our tag: as228e7a21 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: = No match Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag 003094c44b8900ce0eeecaa6-0988066f Our tag: as5095192c [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: = Found Their Call ID: aa5821b8-cf222712-838000b5@192.168.0.250 Their Tag 292799EC-1A35C8CF Our tag: as6b89a935 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #68 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Stopping retransmission on 'aa5821b8-cf222712-838000b5@192.168.0.250' of Response 3: Match Not Found [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] 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=z9hG4bK6f37c1d4;rport From: "Unknown" ;tag=as228e7a21 To: Call-ID: 6cdd59264d9fedce621267464edc2cba@66.114.80.26 Date: Tue, 06 Feb 2007 19:04:57 GMT CSeq: 102 NOTIFY Content-Length: 0 <-------------> [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK6f37c1d4;rport (63) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 2: From: "Unknown" ;tag=as228e7a21 (57) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 3: To: (46) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 6cdd59264d9fedce621267464edc2cba@66.114.80.26 (54) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:04:57 GMT (35) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 6: CSeq: 102 NOTIFY (16) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 7: Content-Length: 0 (17) [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Header 8: (0) [Feb 6 14:04:57] VERBOSE[28216] logger.c: --- (8 headers 0 lines) --- [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: = Found Their Call ID: 6cdd59264d9fedce621267464edc2cba@66.114.80.26 Their Tag Our tag: as228e7a21 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #70 [Feb 6 14:04:57] DEBUG[28216] chan_sip.c: Stopping retransmission on '6cdd59264d9fedce621267464edc2cba@66.114.80.26' of Request 102: Match Not Found [Feb 6 14:04:57] VERBOSE[28216] logger.c: Really destroying SIP dialog '6cdd59264d9fedce621267464edc2cba@66.114.80.26' Method: NOTIFY [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Switching spy 'MixMonitor' on 'SIP/xyz011101-081c3808' to write-trigger mode [Feb 6 14:04:57] DEBUG[28222] channel.c: Triggering queue flush for spy 'MixMonitor' on 'SIP/xyz011101-081c3808' [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:57] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Triggering queue flush for spy 'MixMonitor' on 'SIP/xyz011101-081c3808' [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28216] chan_sip.c: Auto destroying SIP dialog '079a4aa771926a077ca0260c255137c5@66.114.80.26' [Feb 6 14:04:58] DEBUG[28216] chan_sip.c: Destroying SIP dialog 079a4aa771926a077ca0260c255137c5@66.114.80.26 [Feb 6 14:04:58] VERBOSE[28216] logger.c: Really destroying SIP dialog '079a4aa771926a077ca0260c255137c5@66.114.80.26' Method: REGISTER [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Triggering queue flush for spy 'MixMonitor' on 'SIP/xyz011101-081c3808' [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:58] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Auto destroying SIP dialog '003094c4-4b890004-43a68a92-631d873f@192.168.0.217' [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Destroying SIP dialog 003094c4-4b890004-43a68a92-631d873f@192.168.0.217 [Feb 6 14:04:59] VERBOSE[28216] logger.c: Really destroying SIP dialog '003094c4-4b890004-43a68a92-631d873f@192.168.0.217' Method: REGISTER [Feb 6 14:04:59] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:59] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:59] DEBUG[28222] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=28) [Feb 6 14:04:59] DEBUG[28222] channel.c: Triggering queue flush for spy 'MixMonitor' on 'SIP/xyz011101-081c3808' [Feb 6 14:04:59] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1028 ---> BYE sip:111@66.114.80.26:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK2727f596 From: ;tag=003094c44b8900ce0eeecaa6-0988066f To: "poly work" ;tag=as5095192c Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Date: Tue, 06 Feb 2007 19:04:59 GMT CSeq: 101 BYE User-Agent: CSCO/7 Content-Length: 0 <-------------> [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 0: BYE sip:111@66.114.80.26:5060 SIP/2.0 (37) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK2727f596 (58) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 2: From: ;tag=003094c44b8900ce0eeecaa6-0988066f (86) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 3: To: "poly work" ;tag=as5095192c (53) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 4: Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 (54) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 5: Date: Tue, 06 Feb 2007 19:04:59 GMT (35) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 6: CSeq: 101 BYE (13) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 7: User-Agent: CSCO/7 (18) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 8: Content-Length: 0 (17) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 9: (0) [Feb 6 14:04:59] VERBOSE[28216] logger.c: --- (9 headers 0 lines) --- [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: = Found Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag 003094c44b8900ce0eeecaa6-0988066f Our tag: as5095192c [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Feb 6 14:04:59] VERBOSE[28216] logger.c: Sending to 66.114.80.25 : 1028 (NAT) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Received bye, issuing owner hangup [Feb 6 14:04:59] VERBOSE[28216] logger.c: <--- Transmitting (NAT) to 66.114.80.25:1028 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK2727f596;received=66.114.80.25 From: ;tag=003094c44b8900ce0eeecaa6-0988066f To: "poly work" ;tag=as5095192c Call-ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 CSeq: 101 BYE User-Agent: AcePBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 6 14:04:59] DEBUG[28222] channel.c: Set channel SIP/12128121207010001-081c8d58 to write format ulaw [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Stopped music on hold on SIP/12128121207010001-081c8d58 [Feb 6 14:04:59] DEBUG[28222] channel.c: Scheduling timer at 0 sample intervals [Feb 6 14:04:59] DEBUG[28222] channel.c: Didn't get a frame from channel: SIP/12128121207010001-081c8d58 [Feb 6 14:04:59] DEBUG[28222] channel.c: Bridge stops bridging channels SIP/xyz011101-081c3808 and SIP/12128121207010001-081c8d58 [Feb 6 14:04:59] DEBUG[28222] channel.c: Hanging up channel 'SIP/12128121207010001-081c8d58' [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: Hangup call SIP/12128121207010001-081c8d58, SIP callid 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26) [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: update_call_counter(12128121207010001) - decrement call limit counter on hangup [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: Updating call counter for outgoing call [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: Call to peer '12128121207010001' removed from call limit 3 [Feb 6 14:04:59] DEBUG[28222] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001 [Feb 6 14:04:59] DEBUG[28222] devicestate.c: Notification of state change to be queued on device/channel SIP/12128121207010001-081c8d58 [Feb 6 14:04:59] DEBUG[28222] rtp.c: Channel '' has no RTP, not doing anything [Feb 6 14:04:59] DEBUG[28222] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Feb 6 14:04:59] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:04:59] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:04:59] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 1 (Not in use) [Feb 6 14:04:59] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - 12128121207010001 [Feb 6 14:04:59] DEBUG[28205] chan_sip.c: Checking device state for peer 12128121207010001 [Feb 6 14:04:59] DEBUG[28205] devicestate.c: Changing state for SIP/12128121207010001 - state 1 (Not in use) [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- AGI Script callprocessing.agi completed, returning 0 [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Hangup' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [100@xyz:4] Hangup("SIP/xyz011101-081c3808", "") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Spawn extension (xyz,100,4) exited non-zero on 'SIP/xyz011101-081c3808' [Feb 6 14:04:59] VERBOSE[28222] logger.c: == Spawn extension (xyz, 100, 4) exited non-zero on 'SIP/xyz011101-081c3808' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Macro' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [h@xyz:1] Macro("SIP/xyz011101-081c3808", "logvar|AGISTATUS") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Function result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Expression result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'GotoIf' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c3808", "1?+1:+2") in new stack [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Log' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c3808", "NOTICE|"[28223]: 1170788692.0: AGISTATUS=SUCCESS"") in new stack [Feb 6 14:04:59] NOTICE[28222] Ext. s: "[28223]: 1170788692.0: AGISTATUS=SUCCESS" [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'NoOp' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c3808", "") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Macro' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [h@xyz:2] Macro("SIP/xyz011101-081c3808", "logvar|DIALSTATUS") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Function result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Expression result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'GotoIf' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c3808", "1?+1:+2") in new stack [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Log' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c3808", "NOTICE|"[28223]: 1170788692.0: DIALSTATUS=ANSWER"") in new stack [Feb 6 14:04:59] NOTICE[28222] Ext. s: "[28223]: 1170788692.0: DIALSTATUS=ANSWER" [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'NoOp' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c3808", "") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Macro' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [h@xyz:3] Macro("SIP/xyz011101-081c3808", "logvar|ANSWEREDTIME") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Function result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Expression result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'GotoIf' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c3808", "1?+1:+2") in new stack [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Log' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c3808", "NOTICE|"[28223]: 1170788692.0: ANSWEREDTIME=4"") in new stack [Feb 6 14:04:59] NOTICE[28222] Ext. s: "[28223]: 1170788692.0: ANSWEREDTIME=4" [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'NoOp' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c3808", "") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Macro' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [h@xyz:4] Macro("SIP/xyz011101-081c3808", "logvar|RTPAUDIOQOS") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Function result is '0' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Expression result is '0' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'GotoIf' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c3808", "0?+1:+2") in new stack [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Goto (macro-logvar,s,3) [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'NoOp' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c3808", "") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Macro' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [h@xyz:5] Macro("SIP/xyz011101-081c3808", "logvar|UNIQUEID") in new stack [Feb 6 14:04:59] DEBUG[28222] pbx.c: Function result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Expression result is '1' [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'GotoIf' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c3808", "1?+1:+2") in new stack [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Goto (macro-logvar,s,2) [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'Log' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c3808", "NOTICE|"[28223]: 1170788692.0: UNIQUEID=1170788692.0"") in new stack [Feb 6 14:04:59] NOTICE[28222] Ext. s: "[28223]: 1170788692.0: UNIQUEID=1170788692.0" [Feb 6 14:04:59] DEBUG[28222] pbx.c: Launching 'NoOp' [Feb 6 14:04:59] VERBOSE[28222] logger.c: -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c3808", "") in new stack [Feb 6 14:04:59] DEBUG[28222] channel.c: Spy MixMonitor removed from channel SIP/xyz011101-081c3808 [Feb 6 14:04:59] DEBUG[28222] cdr_pgsql.c: cdr_pgsql: inserting a CDR record. [Feb 6 14:04:59] DEBUG[28222] 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:04:52','"poly work" <111>','111','h','xyz', 'SIP/xyz011101-081c3808','SIP/12128121207010001-081c8d58','NoOp','',7,4,'ANSWERED',3,'','1170788692.0','2:xyz011101>100') [Feb 6 14:04:59] VERBOSE[28225] logger.c: == End MixMonitor Recording SIP/xyz011101-081c3808 [Feb 6 14:04:59] VERBOSE[28225] logger.c: == Executing [/var/lib/asterisk/agi-bin/_UTILS/MixMonitor.sh /var/spool/asterisk/monitor/02062007-140453-111-100.WAV /var/spool/asterisk/recordings/xyz/02062007-140453-111-100.WAV &] [Feb 6 14:04:59] DEBUG[28222] channel.c: Hanging up channel 'SIP/xyz011101-081c3808' [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: Hangup call SIP/xyz011101-081c3808, SIP callid aa5821b8-cf222712-838000b5@192.168.0.250) [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: Updating call counter for incoming call [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: Call from user 'xyz011101' removed from call limit 3 [Feb 6 14:04:59] VERBOSE[28222] logger.c: Scheduling destruction of SIP dialog 'aa5821b8-cf222712-838000b5@192.168.0.250' in 32000 ms (Method: ACK) [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: Strict routing enforced for session aa5821b8-cf222712-838000b5@192.168.0.250 [Feb 6 14:04:59] VERBOSE[28222] logger.c: set_destination: Parsing for address/port to send to [Feb 6 14:04:59] VERBOSE[28222] logger.c: set_destination: set destination to 192.168.0.250, port 5060 [Feb 6 14:04:59] VERBOSE[28222] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1025: BYE sip:xyz011101@192.168.0.250 SIP/2.0 Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK3ecd94fc;rport From: ;tag=as6b89a935 To: "poly work" ;tag=292799EC-1A35C8CF Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 CSeq: 102 BYE User-Agent: AcePBX Max-Forwards: 70 Content-Length: 0 --- [Feb 6 14:04:59] DEBUG[28222] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #72 [Feb 6 14:04:59] DEBUG[28222] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c3808 [Feb 6 14:04:59] DEBUG[28205] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101 [Feb 6 14:04:59] DEBUG[28205] chan_sip.c: Checking device state for peer xyz011101 [Feb 6 14:04:59] DEBUG[28205] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use) [Feb 6 14:04:59] VERBOSE[28216] logger.c: <--- SIP read from 66.114.80.25:1025 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK3ecd94fc;rport From: ;tag=as6b89a935 To: "poly work" ;tag=292799EC-1A35C8CF CSeq: 102 BYE Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 Content-Length: 0 <-------------> [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK3ecd94fc;rport (63) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 2: From: ;tag=as6b89a935 (61) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 3: To: "poly work" ;tag=292799EC-1A35C8CF (73) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 4: CSeq: 102 BYE (13) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 5: Call-ID: aa5821b8-cf222712-838000b5@192.168.0.250 (49) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 6: Contact: (38) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 8: Content-Length: 0 (17) [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Header 9: (0) [Feb 6 14:04:59] VERBOSE[28216] logger.c: --- (9 headers 0 lines) --- [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: = No match Their Call ID: 1b057f796d2c8e583b918d911e00a8cd@66.114.80.26 Their Tag 003094c44b8900ce0eeecaa6-0988066f Our tag: as5095192c [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: = Found Their Call ID: aa5821b8-cf222712-838000b5@192.168.0.250 Their Tag 292799EC-1A35C8CF Our tag: as6b89a935 [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #72 [Feb 6 14:04:59] DEBUG[28216] chan_sip.c: Stopping retransmission on 'aa5821b8-cf222712-838000b5@192.168.0.250' of Request 102: Match Not Found [Feb 6 14:04:59] VERBOSE[28216] logger.c: SIP Response message for INCOMING dialog BYE arrived [Feb 6 14:04:59] VERBOSE[28216] logger.c: Really destroying SIP dialog '1b057f796d2c8e583b918d911e00a8cd@66.114.80.26' Method: BYE [Feb 6 14:04:59] VERBOSE[28216] logger.c: Really destroying SIP dialog 'aa5821b8-cf222712-838000b5@192.168.0.250' Method: ACK