<--- SIP read from 66.114.80.25:1025 --->
INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5b312aca5C92B5CB
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>
CSeq: 1 INVITE
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
Contact: <sip:xyz011101@192.168.0.250>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098
Supported: 100rel,replaces
Allow-Events: talk,hold,conference
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 212

v=0
o=- 1170106822 1170106822 IN IP4 192.168.0.250
s=Polycom IP Phone
c=IN IP4 192.168.0.250
t=0 0
a=sendrecv
m=audio 2222 RTP/AVP 0 8 18
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000

<------------->
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 0: INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (59)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5b312aca5C92B5CB (61)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F (75)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1100@pbxtest.acecape.com;user=phone> (45)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 4: CSeq: 1 INVITE (14)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 5: Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250 (49)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 6: Contact: <sip:xyz011101@192.168.0.250> (38)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 9: Supported: 100rel,replaces (26)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 11: Max-Forwards: 70 (16)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 12: Content-Type: application/sdp (29)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 13: Content-Length: 212 (19)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 14:  (0)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: v=0 (3)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: o=- 1170106822 1170106822 IN IP4 192.168.0.250 (46)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: s=Polycom IP Phone (18)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: t=0 0 (5)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=sendrecv (10)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: m=audio 2222 RTP/AVP 0 8 18 (27)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: --- (14 headers 10 lines) ---
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: = No match Their Call ID: 003094c4-4b890006-5d336920-4df7e81c@192.168.0.217 Their Tag  Our tag: as188c219d
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: = No match Their Call ID: 5f02d6cf319afb1201d172d272c94f84@66.114.80.26 Their Tag bb62d7e482cc1e58bd69683900d56829.4f10 Our tag: as0e8190e2
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: = No match Their Call ID: 53f729967cd10f0746876bb05a64441c@66.114.80.26 Their Tag  Our tag: as6df90df2
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Setting NAT on RTP to On
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Allocating new SIP dialog for e1bafb54-863238fe-11d923a5@192.168.0.250 - INVITE (With RTP)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces"
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Found SIP option: -100rel-
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Matched SIP option: 100rel
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Found SIP option: -replaces-
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Matched SIP option: replaces
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1025 (NAT)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Using INVITE request as basis request - e1bafb54-863238fe-11d923a5@192.168.0.250
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Setting NAT on RTP to On
[Jan 30 14:50:34] VERBOSE[7368] logger.c: 
<--- Reliably Transmitting (NAT) to 66.114.80.25:1025 --->
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5b312aca5C92B5CB;received=66.114.80.25
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as5299126e
Call-ID: e1bafb54-863238fe-11d923a5@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="530c73e9"
Content-Length: 0


<------------>
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #532
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Scheduling destruction of SIP dialog 'e1bafb54-863238fe-11d923a5@192.168.0.250' in 32000 ms (Method: INVITE)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found user 'xyz011101'
[Jan 30 14:50:34] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1025 --->
ACK sip:1100@pbxtest.acecape.com:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5b312aca5C92B5CB
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as5299126e
CSeq: 1 ACK
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
Contact: <sip:xyz011101@192.168.0.250>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098
Max-Forwards: 70
Content-Length: 0


<------------->
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 0: ACK sip:1100@pbxtest.acecape.com:5060 SIP/2.0 (45)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5b312aca5C92B5CB (61)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F (75)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as5299126e (60)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 4: CSeq: 1 ACK (11)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 5: Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250 (49)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 6: Contact: <sip:xyz011101@192.168.0.250> (38)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 9: Max-Forwards: 70 (16)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 10: Content-Length: 0 (17)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 11:  (0)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: --- (11 headers 0 lines) ---
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: = Found Their Call ID: e1bafb54-863238fe-11d923a5@192.168.0.250 Their Tag 63379DC8-F345379F Our tag: as5299126e
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #532
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Stopping retransmission on 'e1bafb54-863238fe-11d923a5@192.168.0.250' of Response 1: Match Not Found
[Jan 30 14:50:34] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1025 --->
INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK310e7bb9BA5803B2
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>
CSeq: 2 INVITE
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
Contact: <sip:xyz011101@192.168.0.250>
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="530c73e9", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="1fbb3330442ce2b3341de47147d67528", algorithm=MD5
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 212

v=0
o=- 1170106822 1170106822 IN IP4 192.168.0.250
s=Polycom IP Phone
c=IN IP4 192.168.0.250
t=0 0
a=sendrecv
m=audio 2222 RTP/AVP 0 8 18
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000

<------------->
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 0: INVITE sip:1100@pbxtest.acecape.com:5060;user=phone SIP/2.0 (59)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK310e7bb9BA5803B2 (61)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F (75)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1100@pbxtest.acecape.com;user=phone> (45)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 4: CSeq: 2 INVITE (14)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 5: Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250 (49)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 6: Contact: <sip:xyz011101@192.168.0.250> (38)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 9: Supported: 100rel,replaces (26)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="530c73e9", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="1fbb3330442ce2b3341de47147d67528", algorithm=MD5 (198)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 12: Max-Forwards: 70 (16)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 13: Content-Type: application/sdp (29)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 14: Content-Length: 212 (19)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Header 15:  (0)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: v=0 (3)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: o=- 1170106822 1170106822 IN IP4 192.168.0.250 (46)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: s=Polycom IP Phone (18)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: t=0 0 (5)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=sendrecv (10)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: m=audio 2222 RTP/AVP 0 8 18 (27)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: --- (15 headers 10 lines) ---
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: = Found Their Call ID: e1bafb54-863238fe-11d923a5@192.168.0.250 Their Tag 63379DC8-F345379F Our tag: as5299126e
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1025 (NAT)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Using INVITE request as basis request - e1bafb54-863238fe-11d923a5@192.168.0.250
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Setting NAT on RTP to On
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found user 'xyz011101'
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found RTP audio format 0
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found RTP audio format 8
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found RTP audio format 18
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.250:2222
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found description format PCMU for ID 0
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found description format PCMA for ID 8
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Found description format G729 for ID 18
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: T38 state changed to 0 on channel <none>
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.250:2222
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Checking SIP call limits for device xyz011101
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Updating call counter for incoming call
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: Call from user 'xyz011101' is 1 out of 2
[Jan 30 14:50:34] VERBOSE[7368] logger.c: Looking for 1100 in xyz (domain pbxtest.acecape.com)
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: *** Our native formats are 0x4 (ulaw) 
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) 
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: *** Our capabilities are 0x4 (ulaw) 
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: This channel will not be able to handle video.
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: build_route: Contact hop: <sip:xyz011101@192.168.0.250>
[Jan 30 14:50:34] VERBOSE[7368] logger.c: list_route: hop: <sip:xyz011101@192.168.0.250>
[Jan 30 14:50:34] DEBUG[7368] chan_sip.c: SIP/xyz011101-081c1bf0: New call is still down.... Trying... 
[Jan 30 14:50:34] VERBOSE[7368] logger.c: 
<--- Transmitting (NAT) to 66.114.80.25:1025 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK310e7bb9BA5803B2;received=66.114.80.25
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
CSeq: 2 INVITE
User-Agent: AcePBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1100@66.114.80.26>
Content-Length: 0


<------------>
[Jan 30 14:50:34] DEBUG[7368] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c1bf0
[Jan 30 14:50:34] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101
[Jan 30 14:50:34] DEBUG[7359] chan_sip.c: Checking device state for peer xyz011101
[Jan 30 14:50:34] DEBUG[7359] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use)
[Jan 30 14:50:34] DEBUG[7546] pbx.c: Launching 'Set'
[Jan 30 14:50:34] VERBOSE[7546] logger.c:     -- Executing [1100@xyz:1] Set("SIP/xyz011101-081c1bf0", "TIMEOUT(absolute)=10800") in new stack
[Jan 30 14:50:34] VERBOSE[7546] logger.c:     -- Channel will hangup at 2007-01-30 22:50:34 UTC.
[Jan 30 14:50:34] DEBUG[7546] pbx.c: Launching 'AGI'
[Jan 30 14:50:34] VERBOSE[7546] logger.c:     -- Executing [1100@xyz:2] AGI("SIP/xyz011101-081c1bf0", "callprocessing.agi") in new stack
[Jan 30 14:50:34] VERBOSE[7546] logger.c:     -- Launched AGI Script /usr/local/asterisk/var/lib/asterisk/agi-bin/callprocessing.agi
[Jan 30 14:50:35] DEBUG[7546] pbx.c: Function result is 'xyz011101'
[Jan 30 14:50:36] VERBOSE[7546] logger.c:     -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=2:xyz011101>1100)
[Jan 30 14:50:36] VERBOSE[7546] logger.c:     -- AGI Script Executing Application: (Set) Options: (CALLERID(name)=poly work|CALLERID(num)=111)
[Jan 30 14:50:36] VERBOSE[7546] logger.c:     -- AGI Script Executing Application: (Dial) Options: (SIP/1212812120701100|180|)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Setting NAT on RTP to On
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: *** Our native formats are 0x4 (ulaw) 
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: *** Joint capabilities are 0x0 (nothing) 
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: *** Our capabilities are 0x4 (ulaw) 
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: This channel will not be able to handle video.
[Jan 30 14:50:36] DEBUG[7546] channel.c: Not copying variable CP_PID.
[Jan 30 14:50:36] DEBUG[7546] channel.c: Not copying variable STACK-xyz-1100-2.
[Jan 30 14:50:36] DEBUG[7546] channel.c: Not copying variable STACK-xyz-1100-1.
[Jan 30 14:50:36] DEBUG[7546] channel.c: Not copying variable SIPCALLID.
[Jan 30 14:50:36] DEBUG[7546] channel.c: Not copying variable SIPUSERAGENT.
[Jan 30 14:50:36] DEBUG[7546] channel.c: Not copying variable SIPDOMAIN.
[Jan 30 14:50:36] DEBUG[7546] channel.c: Not copying variable SIPURI.
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Outgoing Call for 1212812120701100
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Updating call counter for outgoing call
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Call to peer '1212812120701100' is 5 out of 5
[Jan 30 14:50:36] DEBUG[7546] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Our T38 capability (0), joint T38 capability (0)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: False
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) 
[Jan 30 14:50:36] VERBOSE[7546] logger.c: Audio is at 66.114.80.26 port 42908
[Jan 30 14:50:36] VERBOSE[7546] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: -- Done with adding codecs to SDP
[Jan 30 14:50:36] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 0: INVITE sip:1212812120701100@192.168.0.217:5060 SIP/2.0 (54)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport (63)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 2: From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7 (55)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 3: To: <sip:1212812120701100@192.168.0.217:5060> (45)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 4: Contact: <sip:111@66.114.80.26> (31)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 5: Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 (54)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 7: User-Agent: AcePBX (18)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 8: Max-Forwards: 70 (16)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 9: Date: Tue, 30 Jan 2007 19:50:36 GMT (35)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 11: Supported: replaces (19)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 12: Content-Type: application/sdp (29)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 13: Content-Length: 182 (19)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Header 14:  (0)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: v=0 (3)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: o=root 7546 7546 IN IP4 66.114.80.26 (36)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: s=session (9)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: c=IN IP4 66.114.80.26 (21)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: t=0 0 (5)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: m=audio 42908 RTP/AVP 0 (23)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: a=silenceSupp:off - - - - (25)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: a=ptime:20 (10)
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: Line: a=sendrecv (10)
[Jan 30 14:50:36] VERBOSE[7546] logger.c: Reliably Transmitting (NAT) to 66.114.80.25:1027:
INVITE sip:1212812120701100@192.168.0.217:5060 SIP/2.0
Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport
From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7
To: <sip:1212812120701100@192.168.0.217:5060>
Contact: <sip:111@66.114.80.26>
Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
CSeq: 102 INVITE
User-Agent: AcePBX
Max-Forwards: 70
Date: Tue, 30 Jan 2007 19:50:36 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 182

v=0
o=root 7546 7546 IN IP4 66.114.80.26
s=session
c=IN IP4 66.114.80.26
t=0 0
m=audio 42908 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Jan 30 14:50:36] DEBUG[7546] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #534
[Jan 30 14:50:36] VERBOSE[7546] logger.c:     -- Called 1212812120701100
[Jan 30 14:50:36] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100
[Jan 30 14:50:36] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100
[Jan 30 14:50:36] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 7 (Ring+Inuse)
[Jan 30 14:50:36] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1027 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport
From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7
To: <sip:1212812120701100@192.168.0.217:5060>
Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
Date: Tue, 30 Jan 2007 19:50:36 GMT
CSeq: 102 INVITE
Server: CSCO/7
Contact: <sip:1212812120701100@192.168.0.217:5060>
Content-Length: 0


<------------->
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 100 Trying (18)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport (63)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7 (55)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1212812120701100@192.168.0.217:5060> (45)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 (54)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:50:36 GMT (35)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 7: Server: CSCO/7 (14)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 8: Contact: <sip:1212812120701100@192.168.0.217:5060> (50)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 9: Content-Length: 0 (17)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 10:  (0)
[Jan 30 14:50:36] VERBOSE[7368] logger.c: --- (10 headers 0 lines) ---
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: = Found Their Call ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 Their Tag  Our tag: as54d214b7
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: *** SIP TIMER: Cancelling retransmission #534 - INVITE (got response)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26' Request 102: Found
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: SIP response 100 to standard invite
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Auto destroying SIP dialog '5f02d6cf319afb1201d172d272c94f84@66.114.80.26'
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Destroying SIP dialog 5f02d6cf319afb1201d172d272c94f84@66.114.80.26
[Jan 30 14:50:36] VERBOSE[7368] logger.c: Really destroying SIP dialog '5f02d6cf319afb1201d172d272c94f84@66.114.80.26' Method: REGISTER
[Jan 30 14:50:36] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1027 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport
From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7
To: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b
Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
Date: Tue, 30 Jan 2007 19:50:36 GMT
CSeq: 102 INVITE
Server: CSCO/7
Contact: <sip:1212812120701100@192.168.0.217:5060>
Content-Length: 0


<------------->
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport (63)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7 (55)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b (83)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 (54)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:50:36 GMT (35)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 7: Server: CSCO/7 (14)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 8: Contact: <sip:1212812120701100@192.168.0.217:5060> (50)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 9: Content-Length: 0 (17)
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: Header 10:  (0)
[Jan 30 14:50:36] VERBOSE[7368] logger.c: --- (10 headers 0 lines) ---
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: = Found Their Call ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 Their Tag  Our tag: as54d214b7
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26' Request 102: Found
[Jan 30 14:50:36] DEBUG[7368] chan_sip.c: SIP response 180 to standard invite
[Jan 30 14:50:36] DEBUG[7368] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100-081b9120
[Jan 30 14:50:36] VERBOSE[7546] logger.c:     -- SIP/1212812120701100-081b9120 is ringing
[Jan 30 14:50:36] VERBOSE[7546] 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=z9hG4bK310e7bb9BA5803B2;received=66.114.80.25
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
CSeq: 2 INVITE
User-Agent: AcePBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1100@66.114.80.26>
Content-Length: 0


<------------>
[Jan 30 14:50:36] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100
[Jan 30 14:50:36] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100
[Jan 30 14:50:36] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 7 (Ring+Inuse)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Auto destroying SIP dialog '003094c4-4b890006-5d336920-4df7e81c@192.168.0.217'
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Destroying SIP dialog 003094c4-4b890006-5d336920-4df7e81c@192.168.0.217
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Really destroying SIP dialog '003094c4-4b890006-5d336920-4df7e81c@192.168.0.217' Method: REGISTER
[Jan 30 14:50:38] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1027 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport
From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7
To: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b
Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
Date: Tue, 30 Jan 2007 19:50:38 GMT
CSeq: 102 INVITE
Server: CSCO/7
Contact: <sip:1212812120701100@192.168.0.217:5060>
Content-Type: application/sdp
Content-Length: 142

v=0
o=Cisco-SIPUA 9591 24404 IN IP4 192.168.0.217
s=SIP Call
c=IN IP4 192.168.0.217
t=0 0
m=audio 18032 RTP/AVP 0
a=rtpmap:0 PCMU/8000

<------------->
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 200 OK (14)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK44589b64;rport (63)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7 (55)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b (83)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 (54)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:50:38 GMT (35)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 6: CSeq: 102 INVITE (16)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 7: Server: CSCO/7 (14)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 8: Contact: <sip:1212812120701100@192.168.0.217:5060> (50)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 9: Content-Type: application/sdp (29)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 10: Content-Length: 142 (19)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 11:  (0)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Line: v=0 (3)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Line: o=Cisco-SIPUA 9591 24404 IN IP4 192.168.0.217 (45)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Line: s=SIP Call (10)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Line: c=IN IP4 192.168.0.217 (22)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Line: t=0 0 (5)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Line: m=audio 18032 RTP/AVP 0 (23)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Jan 30 14:50:38] VERBOSE[7368] logger.c: --- (11 headers 7 lines) ---
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: = Found Their Call ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 Their Tag 003094c44b89004e74674a16-4ce6fb5b Our tag: as54d214b7
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Acked pending invite 102
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Stopping retransmission on '6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26' of Request 102: Match Not Found
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: SIP response 200 to standard invite
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Found RTP audio format 0
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.217:18032
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Found description format PCMU for ID 0
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: T38 state changed to 0 on channel SIP/1212812120701100-081b9120
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.217:18032
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: We have an owner, now see if we need to change this call
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Updating call counter for outgoing call
[Jan 30 14:50:38] DEBUG[7368] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: build_route: Contact hop: <sip:1212812120701100@192.168.0.217:5060>
[Jan 30 14:50:38] VERBOSE[7368] logger.c: list_route: hop: <sip:1212812120701100@192.168.0.217:5060>
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Strict routing enforced for session 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
[Jan 30 14:50:38] VERBOSE[7368] logger.c: set_destination: Parsing <sip:1212812120701100@192.168.0.217:5060> for address/port to send to
[Jan 30 14:50:38] VERBOSE[7368] logger.c: set_destination: set destination to 192.168.0.217, port 5060
[Jan 30 14:50:38] VERBOSE[7368] logger.c: Transmitting (NAT) to 66.114.80.25:1027:
ACK sip:1212812120701100@192.168.0.217:5060 SIP/2.0
Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK0785f38c;rport
From: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7
To: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b
Contact: <sip:111@66.114.80.26>
Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
CSeq: 102 ACK
User-Agent: AcePBX
Max-Forwards: 70
Content-Length: 0


---
[Jan 30 14:50:38] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100
[Jan 30 14:50:38] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100
[Jan 30 14:50:38] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 3 (Busy)
[Jan 30 14:50:38] DEBUG[7546] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100-081b9120
[Jan 30 14:50:38] VERBOSE[7546] logger.c:     -- SIP/1212812120701100-081b9120 answered SIP/xyz011101-081c1bf0
[Jan 30 14:50:38] DEBUG[7546] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c1bf0
[Jan 30 14:50:38] DEBUG[7546] chan_sip.c: SIP answering channel: SIP/xyz011101-081c1bf0
[Jan 30 14:50:38] DEBUG[7546] chan_sip.c: Setting framing from config on incoming call
[Jan 30 14:50:38] DEBUG[7546] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 30 14:50:38] DEBUG[7546] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jan 30 14:50:38] VERBOSE[7546] logger.c: Audio is at 66.114.80.26 port 45546
[Jan 30 14:50:38] VERBOSE[7546] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jan 30 14:50:38] DEBUG[7546] chan_sip.c: -- Done with adding codecs to SDP
[Jan 30 14:50:38] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:38] DEBUG[7546] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 30 14:50:38] VERBOSE[7546] 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=z9hG4bK310e7bb9BA5803B2;received=66.114.80.25
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
CSeq: 2 INVITE
User-Agent: AcePBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1100@66.114.80.26>
Content-Type: application/sdp
Content-Length: 182

v=0
o=root 7546 7546 IN IP4 66.114.80.26
s=session
c=IN IP4 66.114.80.26
t=0 0
m=audio 45546 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Jan 30 14:50:38] DEBUG[7546] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #536
[Jan 30 14:50:38] VERBOSE[7546] logger.c:     -- Packet2Packet bridging SIP/xyz011101-081c1bf0 and SIP/1212812120701100-081b9120
[Jan 30 14:50:38] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100
[Jan 30 14:50:38] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100
[Jan 30 14:50:38] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 3 (Busy)
[Jan 30 14:50:38] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101
[Jan 30 14:50:38] DEBUG[7359] chan_sip.c: Checking device state for peer xyz011101
[Jan 30 14:50:38] DEBUG[7359] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use)
[Jan 30 14:50:38] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1025 --->
ACK sip:1100@66.114.80.26 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5755dae67275ACC7
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
CSeq: 2 ACK
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
Contact: <sip:xyz011101@192.168.0.250>
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="530c73e9", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="1fbb3330442ce2b3341de47147d67528", algorithm=MD5
Max-Forwards: 70
Content-Length: 0


<------------->
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 0: ACK sip:1100@66.114.80.26 SIP/2.0 (33)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK5755dae67275ACC7 (61)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F (75)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3 (60)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 4: CSeq: 2 ACK (11)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 5: Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250 (49)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 6: Contact: <sip:xyz011101@192.168.0.250> (38)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 9: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="530c73e9", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="1fbb3330442ce2b3341de47147d67528", algorithm=MD5 (198)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 10: Max-Forwards: 70 (16)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 11: Content-Length: 0 (17)
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Header 12:  (0)
[Jan 30 14:50:38] VERBOSE[7368] logger.c: --- (12 headers 0 lines) ---
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: = No match Their Call ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 Their Tag 003094c44b89004e74674a16-4ce6fb5b Our tag: as54d214b7
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: = Found Their Call ID: e1bafb54-863238fe-11d923a5@192.168.0.250 Their Tag 63379DC8-F345379F Our tag: as20dca0a3
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #536
[Jan 30 14:50:38] DEBUG[7368] chan_sip.c: Stopping retransmission on 'e1bafb54-863238fe-11d923a5@192.168.0.250' of Response 2: Match Not Found
[Jan 30 14:50:38] DEBUG[7546] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:18032
[Jan 30 14:50:38] DEBUG[7546] rtp.c: RTP NAT: Got audio from other end. Now sending to address 66.114.80.25:2222
[Jan 30 14:50:40] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1025 --->
INVITE sip:1100@66.114.80.26 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKc343a0302ECB9561
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
CSeq: 3 INVITE
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
Contact: <sip:xyz011101@192.168.0.250>
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="530c73e9", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="5f53c7d4b51005b3a9d4c828951b5ecb", algorithm=MD5
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 162

v=0
o=- 1170106822 1170106823 IN IP4 192.168.0.250
s=Polycom IP Phone
c=IN IP4 192.168.0.250
t=0 0
m=audio 2222 RTP/AVP 0
a=sendonly
a=rtpmap:0 PCMU/8000

<------------->
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 0: INVITE sip:1100@66.114.80.26 SIP/2.0 (36)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bKc343a0302ECB9561 (61)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F (75)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3 (60)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 4: CSeq: 3 INVITE (14)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 5: Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250 (49)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 6: Contact: <sip:xyz011101@192.168.0.250> (38)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 9: Supported: 100rel,replaces (26)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 10: Allow-Events: talk,hold,conference (34)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 11: Proxy-Authorization: Digest username="xyz011101", realm="acepbx.com", nonce="530c73e9", uri="sip:1100@pbxtest.acecape.com:5060;user=phone", response="5f53c7d4b51005b3a9d4c828951b5ecb", algorithm=MD5 (198)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 12: Max-Forwards: 70 (16)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 13: Content-Type: application/sdp (29)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 14: Content-Length: 162 (19)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 15:  (0)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: v=0 (3)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: o=- 1170106822 1170106823 IN IP4 192.168.0.250 (46)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: s=Polycom IP Phone (18)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: c=IN IP4 192.168.0.250 (22)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: t=0 0 (5)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: m=audio 2222 RTP/AVP 0 (22)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: a=sendonly (10)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Jan 30 14:50:40] VERBOSE[7368] logger.c: --- (15 headers 8 lines) ---
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: = No match Their Call ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 Their Tag 003094c44b89004e74674a16-4ce6fb5b Our tag: as54d214b7
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: = Found Their Call ID: e1bafb54-863238fe-11d923a5@192.168.0.250 Their Tag 63379DC8-F345379F Our tag: as20dca0a3
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1025 (NAT)
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Found RTP audio format 0
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.250:2222
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Found description format PCMU for ID 0
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: T38 state changed to 0 on channel SIP/xyz011101-081c1bf0
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Peer audio RTP is at port 192.168.0.250:2222
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: We're settling with these formats: 0x4 (ulaw)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: We have an owner, now see if we need to change this call
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Got a SIP re-invite for call e1bafb54-863238fe-11d923a5@192.168.0.250
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: SIP/xyz011101-081c1bf0: This call is UP.... 
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Setting framing from config on incoming call
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Audio is at 66.114.80.26 port 45546
[Jan 30 14:50:40] VERBOSE[7368] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: -- Done with adding codecs to SDP
[Jan 30 14:50:40] DEBUG[7368] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw)
[Jan 30 14:50:40] VERBOSE[7368] 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=z9hG4bKc343a0302ECB9561;received=66.114.80.25
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
CSeq: 3 INVITE
User-Agent: AcePBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:1100@66.114.80.26>
Content-Type: application/sdp
Content-Length: 182

v=0
o=root 7546 7547 IN IP4 66.114.80.26
s=session
c=IN IP4 66.114.80.26
t=0 0
m=audio 45546 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=ptime:20
a=recvonly

<------------>
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #537
[Jan 30 14:50:40] DEBUG[7546] channel.c: Set channel SIP/1212812120701100-081b9120 to write format slin
[Jan 30 14:50:40] VERBOSE[7546] logger.c:     -- Started music on hold, class 'xyz', on channel 'SIP/1212812120701100-081b9120'
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] rtp.c: Ooh, format changed from unknown to ulaw
[Jan 30 14:50:40] DEBUG[7546] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jan 30 14:50:40] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1025 --->
ACK sip:1100@66.114.80.26 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK53e10e9aB631401B
From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
CSeq: 3 ACK
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
Contact: <sip:xyz011101@192.168.0.250>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098
Max-Forwards: 70
Content-Length: 0


<------------->
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 0: ACK sip:1100@66.114.80.26 SIP/2.0 (33)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.250;branch=z9hG4bK53e10e9aB631401B (61)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 2: From: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F (75)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 3: To: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3 (60)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 4: CSeq: 3 ACK (11)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 5: Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250 (49)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 6: Contact: <sip:xyz011101@192.168.0.250> (38)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 9: Max-Forwards: 70 (16)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 10: Content-Length: 0 (17)
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Header 11:  (0)
[Jan 30 14:50:40] VERBOSE[7368] logger.c: --- (11 headers 0 lines) ---
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: = No match Their Call ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 Their Tag 003094c44b89004e74674a16-4ce6fb5b Our tag: as54d214b7
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: = Found Their Call ID: e1bafb54-863238fe-11d923a5@192.168.0.250 Their Tag 63379DC8-F345379F Our tag: as20dca0a3
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #537
[Jan 30 14:50:40] DEBUG[7368] chan_sip.c: Stopping retransmission on 'e1bafb54-863238fe-11d923a5@192.168.0.250' of Response 3: Match Not Found
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:40] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:41] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] DEBUG[7546] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Jan 30 14:50:42] VERBOSE[7368] logger.c: 
<--- SIP read from 66.114.80.25:1027 --->
BYE sip:111@66.114.80.26:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK63cd5aea
From: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b
To: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7
Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
Date: Tue, 30 Jan 2007 19:50:42 GMT
CSeq: 101 BYE
User-Agent: CSCO/7
Content-Length: 0


<------------->
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 0: BYE sip:111@66.114.80.26:5060 SIP/2.0 (37)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK63cd5aea (58)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 2: From: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b (85)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 3: To: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7 (53)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 4: Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 (54)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 5: Date: Tue, 30 Jan 2007 19:50:42 GMT (35)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 6: CSeq: 101 BYE (13)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 7: User-Agent: CSCO/7 (18)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 8: Content-Length: 0 (17)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Header 9:  (0)
[Jan 30 14:50:42] VERBOSE[7368] logger.c: --- (9 headers 0 lines) ---
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: = Found Their Call ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26 Their Tag 003094c44b89004e74674a16-4ce6fb5b Our tag: as54d214b7
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Jan 30 14:50:42] VERBOSE[7368] logger.c: Sending to 66.114.80.25 : 1027 (NAT)
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
[Jan 30 14:50:42] DEBUG[7368] chan_sip.c: Received bye, issuing owner hangup
[Jan 30 14:50:42] VERBOSE[7368] logger.c: 
<--- Transmitting (NAT) to 66.114.80.25:1027 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.217:5060;branch=z9hG4bK63cd5aea;received=66.114.80.25
From: <sip:1212812120701100@192.168.0.217:5060>;tag=003094c44b89004e74674a16-4ce6fb5b
To: "poly work" <sip:111@66.114.80.26>;tag=as54d214b7
Call-ID: 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26
CSeq: 101 BYE
User-Agent: AcePBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:111@66.114.80.26>
Content-Length: 0


<------------>
[Jan 30 14:50:42] DEBUG[7546] channel.c: Set channel SIP/1212812120701100-081b9120 to write format ulaw
[Jan 30 14:50:42] VERBOSE[7546] logger.c:     -- Stopped music on hold on SIP/1212812120701100-081b9120
[Jan 30 14:50:42] DEBUG[7546] rtp.c: Oooh, got a hangup
[Jan 30 14:50:42] DEBUG[7546] channel.c: Returning from native bridge, channels: SIP/xyz011101-081c1bf0, SIP/1212812120701100-081b9120
[Jan 30 14:50:42] DEBUG[7546] channel.c: Hanging up channel 'SIP/1212812120701100-081b9120'
[Jan 30 14:50:42] DEBUG[7546] chan_sip.c: Hangup call SIP/1212812120701100-081b9120, SIP callid 6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26)
[Jan 30 14:50:42] DEBUG[7546] chan_sip.c: update_call_counter(1212812120701100) - decrement call limit counter on hangup
[Jan 30 14:50:42] DEBUG[7546] chan_sip.c: Updating call counter for outgoing call
[Jan 30 14:50:42] DEBUG[7546] chan_sip.c: Call to peer '1212812120701100' removed from call limit 5
[Jan 30 14:50:42] DEBUG[7546] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100
[Jan 30 14:50:42] DEBUG[7546] devicestate.c: Notification of state change to be queued on device/channel SIP/1212812120701100-081b9120
[Jan 30 14:50:42] DEBUG[7546] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jan 30 14:50:42] DEBUG[7546] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jan 30 14:50:42] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100
[Jan 30 14:50:42] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100
[Jan 30 14:50:42] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 2 (In use)
[Jan 30 14:50:42] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - 1212812120701100
[Jan 30 14:50:42] DEBUG[7359] chan_sip.c: Checking device state for peer 1212812120701100
[Jan 30 14:50:42] DEBUG[7359] devicestate.c: Changing state for SIP/1212812120701100 - state 2 (In use)
[Jan 30 14:50:43] VERBOSE[7368] logger.c: Really destroying SIP dialog '6c5ddf9c29abb80a15a821bc2675b797@66.114.80.26' Method: BYE
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- AGI Script callprocessing.agi completed, returning 0
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Hangup'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [1100@xyz:3] Hangup("SIP/xyz011101-081c1bf0", "") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Spawn extension (xyz,1100,3) exited non-zero on 'SIP/xyz011101-081c1bf0'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:   == Spawn extension (xyz, 1100, 3) exited non-zero on 'SIP/xyz011101-081c1bf0'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Macro'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [h@xyz:1] Macro("SIP/xyz011101-081c1bf0", "logvar|AGISTATUS") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Function result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Expression result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'GotoIf'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c1bf0", "1?+1:+2") in new stack
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Goto (macro-logvar,s,2)
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Log'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c1bf0", "NOTICE|"[7547]: 1170186634.20: AGISTATUS=SUCCESS"") in new stack
[Jan 30 14:50:43] NOTICE[7546] Ext. s: "[7547]: 1170186634.20: AGISTATUS=SUCCESS"
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'NoOp'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c1bf0", "") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Macro'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [h@xyz:2] Macro("SIP/xyz011101-081c1bf0", "logvar|DIALSTATUS") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Function result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Expression result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'GotoIf'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c1bf0", "1?+1:+2") in new stack
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Goto (macro-logvar,s,2)
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Log'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c1bf0", "NOTICE|"[7547]: 1170186634.20: DIALSTATUS=ANSWER"") in new stack
[Jan 30 14:50:43] NOTICE[7546] Ext. s: "[7547]: 1170186634.20: DIALSTATUS=ANSWER"
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'NoOp'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c1bf0", "") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Macro'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [h@xyz:3] Macro("SIP/xyz011101-081c1bf0", "logvar|ANSWEREDTIME") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Function result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Expression result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'GotoIf'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c1bf0", "1?+1:+2") in new stack
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Goto (macro-logvar,s,2)
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Log'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c1bf0", "NOTICE|"[7547]: 1170186634.20: ANSWEREDTIME=4"") in new stack
[Jan 30 14:50:43] NOTICE[7546] Ext. s: "[7547]: 1170186634.20: ANSWEREDTIME=4"
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'NoOp'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c1bf0", "") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Macro'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [h@xyz:4] Macro("SIP/xyz011101-081c1bf0", "logvar|RTPAUDIOQOS") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Function result is '0'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Expression result is '0'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'GotoIf'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c1bf0", "0?+1:+2") in new stack
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Goto (macro-logvar,s,3)
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'NoOp'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c1bf0", "") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Macro'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [h@xyz:5] Macro("SIP/xyz011101-081c1bf0", "logvar|UNIQUEID") in new stack
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Function result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Expression result is '1'
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'GotoIf'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:1] GotoIf("SIP/xyz011101-081c1bf0", "1?+1:+2") in new stack
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Goto (macro-logvar,s,2)
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'Log'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:2] Log("SIP/xyz011101-081c1bf0", "NOTICE|"[7547]: 1170186634.20: UNIQUEID=1170186634.20"") in new stack
[Jan 30 14:50:43] NOTICE[7546] Ext. s: "[7547]: 1170186634.20: UNIQUEID=1170186634.20"
[Jan 30 14:50:43] DEBUG[7546] pbx.c: Launching 'NoOp'
[Jan 30 14:50:43] VERBOSE[7546] logger.c:     -- Executing [s@macro-logvar:3] NoOp("SIP/xyz011101-081c1bf0", "") in new stack
[Jan 30 14:50:43] DEBUG[7546] cdr_pgsql.c: cdr_pgsql: inserting a CDR record.
[Jan 30 14:50:43] DEBUG[7546] cdr_pgsql.c: cdr_pgsql: SQL command executed:  INSERT INTO voice_cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-01-30 14:50:34','"poly work" <111>','111','h','xyz', 'SIP/xyz011101-081c1bf0','SIP/1212812120701100-081b9120','NoOp','',9,5,'ANSWERED',3,'','1170186634.20','2:xyz011101>1100')
[Jan 30 14:50:43] DEBUG[7546] channel.c: Hanging up channel 'SIP/xyz011101-081c1bf0'
[Jan 30 14:50:43] DEBUG[7546] chan_sip.c: Hangup call SIP/xyz011101-081c1bf0, SIP callid e1bafb54-863238fe-11d923a5@192.168.0.250)
[Jan 30 14:50:43] DEBUG[7546] chan_sip.c: update_call_counter(xyz011101) - decrement call limit counter on hangup
[Jan 30 14:50:43] DEBUG[7546] chan_sip.c: Updating call counter for incoming call
[Jan 30 14:50:43] DEBUG[7546] chan_sip.c: Call from user 'xyz011101' removed from call limit 2
[Jan 30 14:50:43] VERBOSE[7546] logger.c: Scheduling destruction of SIP dialog 'e1bafb54-863238fe-11d923a5@192.168.0.250' in 32000 ms (Method: ACK)
[Jan 30 14:50:43] DEBUG[7546] chan_sip.c: Strict routing enforced for session e1bafb54-863238fe-11d923a5@192.168.0.250
[Jan 30 14:50:43] VERBOSE[7546] logger.c: set_destination: Parsing <sip:xyz011101@192.168.0.250> for address/port to send to
[Jan 30 14:50:43] VERBOSE[7546] logger.c: set_destination: set destination to 192.168.0.250, port 5060
[Jan 30 14:50:43] VERBOSE[7546] 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=z9hG4bK41752e71;rport
From: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
To: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
CSeq: 102 BYE
User-Agent: AcePBX
Max-Forwards: 70
Content-Length: 0


---
[Jan 30 14:50:43] DEBUG[7546] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id  #540
[Jan 30 14:50:43] DEBUG[7546] devicestate.c: Notification of state change to be queued on device/channel SIP/xyz011101-081c1bf0
[Jan 30 14:50:43] DEBUG[7359] devicestate.c: No provider found, checking channel drivers for SIP - xyz011101
[Jan 30 14:50:43] DEBUG[7359] chan_sip.c: Checking device state for peer xyz011101
[Jan 30 14:50:43] DEBUG[7359] devicestate.c: Changing state for SIP/xyz011101 - state 1 (Not in use)
[Jan 30 14:50:43] VERBOSE[7368] 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=z9hG4bK41752e71;rport
From: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3
To: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F
CSeq: 102 BYE
Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250
Contact: <sip:xyz011101@192.168.0.250>
User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098
Content-Length: 0


<------------->
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 0: SIP/2.0 200 OK (14)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 1: Via: SIP/2.0/UDP 66.114.80.26:5060;branch=z9hG4bK41752e71;rport (63)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 2: From: <sip:1100@pbxtest.acecape.com;user=phone>;tag=as20dca0a3 (62)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 3: To: "poly work" <sip:xyz011101@pbxtest.acecape.com>;tag=63379DC8-F345379F (73)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 4: CSeq: 102 BYE (13)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 5: Call-ID: e1bafb54-863238fe-11d923a5@192.168.0.250 (49)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 6: Contact: <sip:xyz011101@192.168.0.250> (38)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.7.0098 (54)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 8: Content-Length: 0 (17)
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Header 9:  (0)
[Jan 30 14:50:43] VERBOSE[7368] logger.c: --- (9 headers 0 lines) ---
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: = Found Their Call ID: e1bafb54-863238fe-11d923a5@192.168.0.250 Their Tag 63379DC8-F345379F Our tag: as20dca0a3
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #540
[Jan 30 14:50:43] DEBUG[7368] chan_sip.c: Stopping retransmission on 'e1bafb54-863238fe-11d923a5@192.168.0.250' of Request 102: Match Not Found
[Jan 30 14:50:43] VERBOSE[7368] logger.c: SIP Response message for INCOMING dialog BYE arrived
[Jan 30 14:50:43] VERBOSE[7368] logger.c: Really destroying SIP dialog 'e1bafb54-863238fe-11d923a5@192.168.0.250' Method: ACK