*CLI> sip set debug on <--- SIP read from 192.168.1.99:5060 ---> INVITE sip:099@192.168.1.199:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK868f9e2061492387 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: CSeq: 1 INVITE Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 249 v=0 o=- 1172717509 1172717509 IN IP4 192.168.1.99 s=Polycom IP Phone c=IN IP4 192.168.1.99 t=0 0 a=sendrecv m=audio 2248 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 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 52]: INVITE sip:099@192.168.1.199:5060;user=phone SIP/2.0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK868f9e2061492387 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 69]: From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 38]: To: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 14]: CSeq: 1 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 26]: Supported: 100rel,replaces [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 34]: Allow-Events: talk,hold,conference [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 16]: Max-Forwards: 70 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 249 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 45]: o=- 1172717509 1172717509 IN IP4 192.168.1.99 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 18]: s=Polycom IP Phone [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 21]: c=IN IP4 192.168.1.99 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 10]: a=sendrecv [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 31]: m=audio 2248 RTP/AVP 0 8 18 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 --- (14 headers 11 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 Their Tag 4535f1786e09faf Our tag: as28504e61 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for 6600ed56-5253872c-6049974d@192.168.1.99 - INVITE (With RTP) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1829 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1837 parse_sip_options: Found SIP option: -100rel- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1843 parse_sip_options: Matched SIP option: 100rel [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1837 parse_sip_options: Found SIP option: -replaces- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1843 parse_sip_options: Matched SIP option: replaces Sending to 192.168.1.99 : 5060 (no NAT) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:13975 handle_request_invite: Initializing initreq for method INVITE - callid 6600ed56-5253872c-6049974d@192.168.1.99 Using INVITE request as basis request - 6600ed56-5253872c-6049974d@192.168.1.99 No user '099' in SIP users list Found peer '099' for '099' from 192.168.1.99:5060 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off <--- Reliably Transmitting (no NAT) to 192.168.1.99:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK868f9e2061492387;received=192.168.1.99 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: ;tag=as3f70c9f8 Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="192.168.1.199", nonce="792b3762" Content-Length: 0 <------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #50 Scheduling destruction of SIP dialog '6600ed56-5253872c-6049974d@192.168.1.99' in 32000 ms (Method: INVITE) <--- SIP read from 192.168.1.99:5060 ---> ACK sip:099@192.168.1.199:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK868f9e2061492387 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: ;tag=as3f70c9f8 CSeq: 1 ACK Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 38]: ACK sip:099@192.168.1.199:5060 SIP/2.0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK868f9e2061492387 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 69]: From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 53]: To: ;tag=as3f70c9f8 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 16]: Max-Forwards: 70 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as3f70c9f8 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #50 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '6600ed56-5253872c-6049974d@192.168.1.99' of Response 1: Match Found <--- SIP read from 192.168.1.99:5060 ---> INVITE sip:099@192.168.1.199:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK7aa579b9C6F912B8 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: CSeq: 2 INVITE Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Supported: 100rel,replaces Allow-Events: talk,hold,conference Authorization: Digest username="099", realm="192.168.1.199", nonce="792b3762", uri="sip:099@192.168.1.199:5060;user=phone", response="525c8dc08d4f160162541bb03ea00388", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 249 v=0 o=- 1172717509 1172717509 IN IP4 192.168.1.99 s=Polycom IP Phone c=IN IP4 192.168.1.99 t=0 0 a=sendrecv m=audio 2248 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 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 52]: INVITE sip:099@192.168.1.199:5060;user=phone SIP/2.0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK7aa579b9C6F912B8 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 69]: From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 38]: To: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 14]: CSeq: 2 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 26]: Supported: 100rel,replaces [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 34]: Allow-Events: talk,hold,conference [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [182]: Authorization: Digest username="099", realm="192.168.1.199", nonce="792b3762", uri="sip:099@192.168.1.199:5060;user=phone", response="525c8dc08d4f160162541bb03ea00388", algorithm=MD5 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 16]: Max-Forwards: 70 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 14 [ 19]: Content-Length: 249 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 15 [ 0]: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 45]: o=- 1172717509 1172717509 IN IP4 192.168.1.99 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 18]: s=Polycom IP Phone [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 21]: c=IN IP4 192.168.1.99 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 10]: a=sendrecv [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 31]: m=audio 2248 RTP/AVP 0 8 18 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 --- (15 headers 11 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as3f70c9f8 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15271 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.1.99 : 5060 (no NAT) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:13975 handle_request_invite: Initializing initreq for method INVITE - callid 6600ed56-5253872c-6049974d@192.168.1.99 Using INVITE request as basis request - 6600ed56-5253872c-6049974d@192.168.1.99 No user '099' in SIP users list Found peer '099' for '099' from 192.168.1.99:5060 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.99:2248 Found description format PCMU for ID 0 Found description format PCMA for ID 8 Found description format G729 for ID 18 Found description format telephone-event for ID 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.1.99:2248 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:14056 handle_request_invite: Checking SIP call limits for device 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for incoming call [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3375 update_call_counter: Call from peer '099' is 1 out of 4 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099 Looking for 099 in dlc_callforward (domain 192.168.1.199) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4126 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4128 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4159 sip_new: This channel will not be able to handle video. [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:8478 build_route: build_route: Contact hop: list_route: hop: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:14131 handle_request_invite: SIP/099-081f0798: New call is still down.... Trying... <--- Transmitting (no NAT) to 192.168.1.99:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK7aa579b9C6F912B8;received=192.168.1.99 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099-081f0798 [Feb 28 22:05:12] DEBUG[3810]: pbx.c:1693 pbx_extension_helper: Launching 'Dial' -- Executing [099@dlc_callforward:1] Dial("SIP/099-081f0798", "SIP/099&SIP/101") in new stack [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15966 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:12] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK7f885157;rport Max-Forwards: 70 From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Contact: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 103 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 208 confirmed --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #52 Extension Changed 099 new state InUse for Notify User 101 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:12] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1783 obproxy_get: OBPROXY: Not applying OBproxy to this call [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4126 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4128 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4131 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4159 sip_new: This channel will not be able to handle video. [Feb 28 22:05:12] DEBUG[3810]: rtp.c:1677 ast_rtp_make_compatible: Seeded SDP of 'SIP/099-081f89b0' with that of 'SIP/099-081f0798' [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-dlc_callforward-099-1. [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3122 sip_call: Outgoing Call for 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3375 update_call_counter: Call to peer '099' is 2 out of 4 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3140 sip_call: Our T38 capability (0), joint T38 capability (0) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 192.168.1.199 port 19692 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 28 22:05:12] DEBUG[3810]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=25) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1718 initialize_initreq: Initializing initreq for method INVITE - callid 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 35]: INVITE sip:099@192.168.1.99 SIP/2.0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 26]: To: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 32]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 55]: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56232 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 35]: Date: Thu, 01 Mar 2007 03:05:12 GMT [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 19]: Supported: replaces [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 240 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 37]: o=root 3806 3806 IN IP4 192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=session [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 27]: m=audio 19692 RTP/AVP 0 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 192.168.1.99:5060: INVITE sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport Max-Forwards: 70 From: "Kevin Broadfoot" ;tag=as0ac4fbb0 To: Contact: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Date: Thu, 01 Mar 2007 03:05:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 240 v=0 o=root 3806 3806 IN IP4 192.168.1.199 s=session c=IN IP4 192.168.1.199 t=0 0 m=audio 19692 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #53 -- Called 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15966 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1783 obproxy_get: OBPROXY: Not applying OBproxy to this call [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4126 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4128 sip_new: *** Our capabilities are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4131 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4159 sip_new: This channel will not be able to handle video. [Feb 28 22:05:12] DEBUG[3810]: rtp.c:1677 ast_rtp_make_compatible: Seeded SDP of 'SIP/101-081fcfc0' with that of 'SIP/099-081f0798' [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-dlc_callforward-099-1. [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 28 22:05:12] DEBUG[3810]: channel.c:3211 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3122 sip_call: Outgoing Call for 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3375 update_call_counter: Call to peer '101' is 1 out of 4 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:3140 sip_call: Our T38 capability (0), joint T38 capability (0) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 192.168.1.199 port 19680 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 28 22:05:12] DEBUG[3810]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:1718 initialize_initreq: Initializing initreq for method INVITE - callid 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 36]: INVITE sip:101@192.168.1.180 SIP/2.0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 27]: To: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 32]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56232 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 35]: Date: Thu, 01 Mar 2007 03:05:12 GMT [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 19]: Supported: replaces [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 240 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 37]: o=root 3806 3806 IN IP4 192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=session [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 27]: m=audio 19680 RTP/AVP 0 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 192.168.1.180:5060: INVITE sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport Max-Forwards: 70 From: "Kevin Broadfoot" ;tag=as46c41ed7 To: Contact: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Date: Thu, 01 Mar 2007 03:05:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 240 v=0 o=root 3806 3806 IN IP4 192.168.1.199 s=session c=IN IP4 192.168.1.199 t=0 0 m=audio 19680 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #55 -- Called 101 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 7 (Ring+Inuse) [Feb 28 22:05:12] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '7' (Ring+Inuse) but we don't care because they're not a member of any queue. [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK229e0816;rport Max-Forwards: 70 From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Contact: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 104 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 226 early --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #57 Extension Changed 099 new state InUse&Ringing for Notify User 101 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 6 (Ringing) [Feb 28 22:05:12] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK17d99602;rport Max-Forwards: 70 From: sip:101@192.168.1.199:5060;tag=as28504e61 To: Kevin Broadfoot ;tag=4535f1786e09faf Contact: Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 CSeq: 103 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 226 early --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #58 Extension Changed 101 new state Ringing for Notify User 101 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 104 NOTIFY From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK229e0816;rport Content-Length: 0 Retry-After: 6 Contact: Kevin Broadfoot User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 33]: SIP/2.0 500 Server Internal Error [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 104 NOTIFY [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:099@192.168.1.199:5060;tag=as153b45f2 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=b34ef83a9a549de [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK229e0816;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 14]: Retry-After: 6 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag Our tag: as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag Our tag: as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #57 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '351e555ff18e37612dce23dc01b01852@192.168.1.180' of Request 104: Match Found SIP Response message for INCOMING dialog NOTIFY arrived -- Incoming call: Got SIP response 500 "Server Internal Error" back from 192.168.1.180 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 100 Trying Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 102 INVITE From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport Content-Length: 0 User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 47]: To: ;tag=853eec464696386 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 0]: --- (8 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag Our tag: as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2268 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #55 - INVITE (got response) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199' Request 102: Found [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:12287 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 192.168.1.99:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport From: "Kevin Broadfoot" ;tag=as0ac4fbb0 To: ;tag=670E9BA-37EB7A8B CSeq: 102 INVITE Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Contact: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Content-Length: 0 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 62]: From: "Kevin Broadfoot" ;tag=as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: To: ;tag=670E9BA-37EB7A8B [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 55]: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag Our tag: as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2268 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #53 - INVITE (got response) [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '32e035ad3d09a51064af5d9a763be69f@192.168.1.199' Request 102: Found [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:12287 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 103 NOTIFY From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK7f885157;rport Content-Length: 0 Contact: Kevin Broadfoot Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 103 NOTIFY [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:099@192.168.1.199:5060;tag=as153b45f2 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=b34ef83a9a549de [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK7f885157;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Supported: replaces [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #52 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '351e555ff18e37612dce23dc01b01852@192.168.1.180' of Request 103: Match Found SIP Response message for INCOMING dialog NOTIFY arrived <--- SIP read from 192.168.1.99:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport From: "Kevin Broadfoot" ;tag=as0ac4fbb0 To: ;tag=670E9BA-37EB7A8B CSeq: 102 INVITE Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Contact: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Allow-Events: talk,hold,conference Content-Length: 0 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 62]: From: "Kevin Broadfoot" ;tag=as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: To: ;tag=670E9BA-37EB7A8B [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 55]: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 34]: Allow-Events: talk,hold,conference [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '32e035ad3d09a51064af5d9a763be69f@192.168.1.199' Request 102: Found [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:12287 handle_response_invite: SIP response 180 to standard invite [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099-081f89b0 -- SIP/099-081f89b0 is ringing <--- Transmitting (no NAT) to 192.168.1.99:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK7aa579b9C6F912B8;received=192.168.1.99 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: ;tag=as6322d2d3 Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 7 (Ring+Inuse) [Feb 28 22:05:12] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '7' (Ring+Inuse) but we don't care because they're not a member of any queue. [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 CSeq: 103 NOTIFY From: sip:101@192.168.1.199:5060;tag=as28504e61 To: Kevin Broadfoot ;tag=4535f1786e09faf Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK17d99602;rport Content-Length: 0 Contact: Kevin Broadfoot Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 103 NOTIFY [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:101@192.168.1.199:5060;tag=as28504e61 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=4535f1786e09faf [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK17d99602;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Supported: replaces [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 Their Tag 4535f1786e09faf Our tag: as28504e61 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #58 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on 'd86f893a19209a5f32391a395243cbb7@192.168.1.180' of Request 103: Match Found SIP Response message for INCOMING dialog NOTIFY arrived <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 180 Ringing Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 102 INVITE From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport Content-Length: 0 Allow-Events: talk, hold, conference Contact: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 47]: To: ;tag=853eec464696386 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 36]: Allow-Events: talk, hold, conference [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 32]: Contact: [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199' Request 102: Found [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:12287 handle_response_invite: SIP response 180 to standard invite [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081fcfc0 -- SIP/101-081fcfc0 is ringing [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 6 (Ringing) [Feb 28 22:05:12] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 28 22:05:12] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:12] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 102 INVITE From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport Content-Length: 231 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Content-Type: application/sdp Supported: replaces Contact: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 v=0 o=MxSIP 0 589885540 IN IP4 192.168.1.180 s=SIP Call c=IN IP4 192.168.1.180 t=0 0 m=audio 3000 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:off - - - - <-------------> [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 47]: To: ;tag=853eec464696386 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK56decd21;rport [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 19]: Content-Length: 231 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 34]: Allow-Events: talk,hold,conference [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 53]: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 29]: Content-Type: application/sdp [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Supported: replaces [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 32]: Contact: [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 0]: [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 40]: o=MxSIP 0 589885540 IN IP4 192.168.1.180 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 10]: s=SIP Call [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.180 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 26]: m=audio 3000 RTP/AVP 0 101 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 10]: a=ptime:20 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 25]: a=silenceSupp:off - - - - --- (13 headers 11 lines) --- [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2218 __sip_ack: Acked pending invite 102 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199' of Request 102: Match Found [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:12287 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.180:3000 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/101-081fcfc0 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.1.180:3000 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 --- set_address_from_contact host '192.168.1.180' [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:8478 build_route: build_route: Contact hop: list_route: hop: [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.180, port 5060 Transmitting (no NAT) to 192.168.1.180:5060: ACK sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK7298e643;rport Max-Forwards: 70 From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Contact: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r56232 Content-Length: 0 --- -- Call on SIP/101-081fcfc0 left from hold [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081fcfc0 -- SIP/101-081fcfc0 answered SIP/099-081f0798 [Feb 28 22:05:13] DEBUG[3810]: rtp.c:1607 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/099-081f0798' with that of 'SIP/101-081fcfc0' [Feb 28 22:05:13] DEBUG[3810]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/099-081f89b0' [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:3603 sip_hangup: Hangup call SIP/099-081f89b0, SIP callid 32e035ad3d09a51064af5d9a763be69f@192.168.1.199) [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:3612 sip_hangup: update_call_counter(099) - decrement call limit counter on hangup [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:3349 update_call_counter: Call to peer '099' removed from call limit 4 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:3627 sip_hangup: Hanging up channel in state Ringing (not UP) Scheduling destruction of SIP dialog '32e035ad3d09a51064af5d9a763be69f@192.168.1.199' in 32000 ms (Method: INVITE) [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2218 __sip_ack: Acked pending invite 102 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '32e035ad3d09a51064af5d9a763be69f@192.168.1.199' of Request 102: Match Found Reliably Transmitting (no NAT) to 192.168.1.99:5060: CANCEL sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport Max-Forwards: 70 From: "Kevin Broadfoot" ;tag=as0ac4fbb0 To: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 CSeq: 102 CANCEL User-Agent: Asterisk PBX SVN-trunk-r56232 Content-Length: 0 --- [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #60 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) Scheduling destruction of SIP dialog '32e035ad3d09a51064af5d9a763be69f@192.168.1.199' in 32000 ms (Method: INVITE) [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099-081f89b0 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099-081f0798 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:3761 sip_answer: SIP answering channel: SIP/099-081f0798 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:6952 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.1.199 port 19666 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 28 22:05:13] DEBUG[3810]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (no NAT) to 192.168.1.99:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bK7aa579b9C6F912B8;received=192.168.1.99 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: ;tag=as6322d2d3 Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 240 v=0 o=root 3806 3806 IN IP4 192.168.1.199 s=session c=IN IP4 192.168.1.199 t=0 0 m=audio 19666 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #62 [Feb 28 22:05:13] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK11b98e46;rport Max-Forwards: 70 From: sip:101@192.168.1.199:5060;tag=as28504e61 To: Kevin Broadfoot ;tag=4535f1786e09faf Contact: Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 CSeq: 104 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 208 confirmed --- [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #63 Extension Changed 101 new state InUse for Notify User 101 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 28 22:05:13] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:13] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK31289358;rport Max-Forwards: 70 From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Contact: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 105 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 208 confirmed --- [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #64 Extension Changed 099 new state InUse for Notify User 101 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:13] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:13] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:13] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:13] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 <--- SIP read from 192.168.1.99:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport From: "Kevin Broadfoot" ;tag=as0ac4fbb0 To: CSeq: 102 CANCEL Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Contact: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Content-Length: 0 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 62]: From: "Kevin Broadfoot" ;tag=as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 26]: To: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 CANCEL [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 55]: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 17]: Content-Length: 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #60 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '32e035ad3d09a51064af5d9a763be69f@192.168.1.199' of Request 102: Match Found <--- SIP read from 192.168.1.99:5060 ---> SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport From: "Kevin Broadfoot" ;tag=as0ac4fbb0 To: ;tag=670E9BA-37EB7A8B CSeq: 102 INVITE Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Contact: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Content-Length: 0 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 29]: SIP/2.0 487 Request Cancelled [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 62]: From: "Kevin Broadfoot" ;tag=as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: To: ;tag=670E9BA-37EB7A8B [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 55]: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 17]: Content-Length: 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag Our tag: as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '32e035ad3d09a51064af5d9a763be69f@192.168.1.199' of Request 102: Match Not Found [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12287 handle_response_invite: SIP response 487 to standard invite Transmitting (no NAT) to 192.168.1.99:5060: ACK sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK517f2ba5;rport Max-Forwards: 70 From: "Kevin Broadfoot" ;tag=as0ac4fbb0 To: ;tag=670E9BA-37EB7A8B Contact: Call-ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r56232 Content-Length: 0 --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:3349 update_call_counter: Call to peer '099' removed from call limit 4 [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099 [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 1 (Not in use) [Feb 28 22:05:14] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK196a4dde;rport Max-Forwards: 70 From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Contact: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 106 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 209 terminated --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #65 Extension Changed 099 new state Idle for Notify User 101 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 CSeq: 104 NOTIFY From: sip:101@192.168.1.199:5060;tag=as28504e61 To: Kevin Broadfoot ;tag=4535f1786e09faf Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK11b98e46;rport Content-Length: 0 Contact: Kevin Broadfoot Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 104 NOTIFY [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:101@192.168.1.199:5060;tag=as28504e61 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=4535f1786e09faf [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK11b98e46;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Supported: replaces [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 Their Tag 4535f1786e09faf Our tag: as28504e61 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #63 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on 'd86f893a19209a5f32391a395243cbb7@192.168.1.180' of Request 104: Match Found SIP Response message for INCOMING dialog NOTIFY arrived <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 105 NOTIFY From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK31289358;rport Content-Length: 0 Contact: Kevin Broadfoot Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 105 NOTIFY [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:099@192.168.1.199:5060;tag=as153b45f2 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=b34ef83a9a549de [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK31289358;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Supported: replaces [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #64 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '351e555ff18e37612dce23dc01b01852@192.168.1.180' of Request 105: Match Found SIP Response message for INCOMING dialog NOTIFY arrived <--- SIP read from 192.168.1.99:5060 ---> ACK sip:099@192.168.1.199 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bKe6a4b211838FD150 From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 To: ;tag=as6322d2d3 CSeq: 2 ACK Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 33]: ACK sip:099@192.168.1.199 SIP/2.0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 192.168.1.99;branch=z9hG4bKe6a4b211838FD150 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 69]: From: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 53]: To: ;tag=as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 16]: Max-Forwards: 70 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15271 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #62 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '6600ed56-5253872c-6049974d@192.168.1.99' of Response 2: Match Found <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 106 NOTIFY From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK196a4dde;rport Content-Length: 0 Contact: Kevin Broadfoot Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 106 NOTIFY [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:099@192.168.1.199:5060;tag=as153b45f2 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=b34ef83a9a549de [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK196a4dde;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Supported: replaces [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #65 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '351e555ff18e37612dce23dc01b01852@192.168.1.180' of Request 106: Match Found SIP Response message for INCOMING dialog NOTIFY arrived [Feb 28 22:05:14] DEBUG[3810]: chan_iax2.c:7883 iax2_do_register: Allocate call number [Feb 28 22:05:14] DEBUG[3810]: chan_iax2.c:7889 iax2_do_register: Registration created on call 4 [Feb 28 22:05:14] DEBUG[3810]: chan_iax2.c:7883 iax2_do_register: Allocate call number [Feb 28 22:05:14] DEBUG[3810]: chan_iax2.c:7889 iax2_do_register: Registration created on call 5 -- Native bridging SIP/099-081f0798 and SIP/101-081fcfc0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:17627 sip_set_rtp_peer: Sending reinvite on SIP '6600ed56-5253872c-6049974d@192.168.1.99' - It's audio soon redirected to IP 192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 6600ed56-5253872c-6049974d@192.168.1.99 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.99, port 5060 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.1.199 port 19666 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 28 22:05:14] DEBUG[3810]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:1716 initialize_initreq: Initializing already initialized SIP dialog 6600ed56-5253872c-6049974d@192.168.1.99 (presumably reinvite) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 35]: INVITE sip:099@192.168.1.99 SIP/2.0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK03c4d6e4;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 55]: From: ;tag=as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 67]: To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 32]: Contact: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56232 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Supported: replaces [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 239 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 37]: o=root 3806 3807 IN IP4 192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=session [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 26]: m=audio 3000 RTP/AVP 0 101 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 192.168.1.99:5060: INVITE sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK03c4d6e4;rport Max-Forwards: 70 From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 Contact: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 239 v=0 o=root 3806 3807 IN IP4 192.168.1.180 s=session c=IN IP4 192.168.1.180 t=0 0 m=audio 3000 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #67 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:17627 sip_set_rtp_peer: Sending reinvite on SIP '3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199' - It's audio soon redirected to IP 192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.180, port 5060 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 192.168.1.199 port 19680 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 28 22:05:14] DEBUG[3810]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=28) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:1716 initialize_initreq: Initializing already initialized SIP dialog 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 (presumably reinvite) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 36]: INVITE sip:101@192.168.1.180 SIP/2.0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK39c310a2;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 47]: To: ;tag=853eec464696386 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 32]: Contact: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 16]: CSeq: 103 INVITE [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56232 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Supported: replaces [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 237 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 36]: o=root 3806 3807 IN IP4 192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=session [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 21]: c=IN IP4 192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 26]: m=audio 2248 RTP/AVP 0 101 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 192.168.1.180:5060: INVITE sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK39c310a2;rport Max-Forwards: 70 From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Contact: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 103 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 237 v=0 o=root 3806 3807 IN IP4 192.168.1.99 s=session c=IN IP4 192.168.1.99 t=0 0 m=audio 2248 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #68 [Feb 28 22:05:14] DEBUG[3810]: rtp.c:941 ast_rtcp_read: Got RTCP report of 40 bytes [Feb 28 22:05:14] DEBUG[3810]: rtp.c:2792 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 28 22:05:14] DEBUG[3810]: rtp.c:2809 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 28 22:05:14] DEBUG[3810]: rtp.c:2792 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 28 22:05:14] DEBUG[3810]: rtp.c:2809 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 100 Trying Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 103 INVITE From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK39c310a2;rport Content-Length: 0 User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 103 INVITE [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 47]: To: ;tag=853eec464696386 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK39c310a2;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 0]: --- (8 headers 0 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2268 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #68 - INVITE (got response) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199' Request 103: Found [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12285 handle_response_invite: SIP response 100 to RE-invite on outgoing call 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 103 INVITE From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK39c310a2;rport Content-Length: 231 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Content-Type: application/sdp Supported: replaces Contact: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 v=0 o=MxSIP 0 589885540 IN IP4 192.168.1.180 s=SIP Call c=IN IP4 192.168.1.180 t=0 0 m=audio 3000 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=silenceSupp:off - - - - <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 103 INVITE [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 62]: From: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 47]: To: ;tag=853eec464696386 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK39c310a2;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 19]: Content-Length: 231 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 34]: Allow-Events: talk,hold,conference [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 53]: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 29]: Content-Type: application/sdp [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Supported: replaces [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 32]: Contact: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 0]: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 40]: o=MxSIP 0 589885540 IN IP4 192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 10]: s=SIP Call [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.180 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 26]: m=audio 3000 RTP/AVP 0 101 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-15 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 10]: a=ptime:20 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 25]: a=silenceSupp:off - - - - --- (13 headers 11 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2218 __sip_ack: Acked pending invite 103 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199' of Request 103: Match Found [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12285 handle_response_invite: SIP response 200 to RE-invite on outgoing call 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.180:3000 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/101-081fcfc0 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.1.180:3000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 --- set_address_from_contact host '192.168.1.180' [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:8417 build_route: build_route: Retaining previous route: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12418 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12423 handle_response_invite: T38 state changed to 0 on channel SIP [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12426 handle_response_invite: T38 state changed to 0 on channel SIP/101-081fcfc0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.180, port 5060 Transmitting (no NAT) to 192.168.1.180:5060: ACK sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5e4a2de9;rport Max-Forwards: 70 From: "Kevin Broadfoot" ;tag=as46c41ed7 To: ;tag=853eec464696386 Contact: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 103 ACK User-Agent: Asterisk PBX SVN-trunk-r56232 Content-Length: 0 --- [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Feb 28 22:05:14] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 <--- SIP read from 192.168.1.99:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK03c4d6e4;rport From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 CSeq: 102 INVITE Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Content-Type: application/sdp Content-Length: 199 v=0 o=- 1172717510 1172717510 IN IP4 192.168.1.99 s=Polycom IP Phone c=IN IP4 192.168.1.99 t=0 0 m=audio 2248 RTP/AVP 0 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK03c4d6e4;rport [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 55]: From: ;tag=as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 67]: To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 102 INVITE [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 29]: Content-Type: application/sdp [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Content-Length: 199 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 0]: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 45]: o=- 1172717510 1172717510 IN IP4 192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 18]: s=Polycom IP Phone [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 21]: c=IN IP4 192.168.1.99 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 26]: m=audio 2248 RTP/AVP 0 101 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 10]: a=sendrecv [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 9 lines) --- [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2218 __sip_ack: Acked pending invite 102 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #67 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '6600ed56-5253872c-6049974d@192.168.1.99' of Request 102: Match Found [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12285 handle_response_invite: SIP response 200 to RE-invite on outgoing call 6600ed56-5253872c-6049974d@192.168.1.99 Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.99:2248 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/099-081f0798 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.1.99:2248 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for incoming call [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099 --- set_address_from_contact host '192.168.1.99' [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:8478 build_route: build_route: Contact hop: list_route: hop: [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12418 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12423 handle_response_invite: T38 state changed to 0 on channel SIP [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:12426 handle_response_invite: T38 state changed to 0 on channel SIP/099-081f0798 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 6600ed56-5253872c-6049974d@192.168.1.99 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.99, port 5060 Transmitting (no NAT) to 192.168.1.99:5060: ACK sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5616be94;rport Max-Forwards: 70 From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 Contact: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r56232 Content-Length: 0 --- [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 1 (Not in use) [Feb 28 22:05:14] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 22:05:14] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:14] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:16] DEBUG[3810]: chan_iax2.c:7883 iax2_do_register: Allocate call number [Feb 28 22:05:16] DEBUG[3810]: chan_iax2.c:7889 iax2_do_register: Registration created on call 6 <--- SIP read from 192.168.1.180:5060 ---> BYE sip:099@192.168.1.199 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.180;branch=z9hG4bK469a917b8 Max-Forwards: 70 Content-Length: 0 To: "Kevin Broadfoot" ;tag=as46c41ed7 From: ;tag=853eec464696386 Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 751039122 BYE Supported: timer Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 33]: BYE sip:099@192.168.1.199 SIP/2.0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 54]: Via: SIP/2.0/UDP 192.168.1.180;branch=z9hG4bK469a917b8 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 17]: Content-Length: 0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 60]: To: "Kevin Broadfoot" ;tag=as46c41ed7 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 49]: From: ;tag=853eec464696386 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 55]: Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 19]: CSeq: 751039122 BYE [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 16]: Supported: timer [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 19]: Supported: replaces [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 0]: --- (11 headers 0 lines) --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15271 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:14797 handle_request_bye: Initializing initreq for method BYE - callid 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Sending to 192.168.1.180 : 5060 (no NAT) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:1731 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:14854 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (no NAT) to 192.168.1.180:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.180;branch=z9hG4bK469a917b8;received=192.168.1.180 From: ;tag=853eec464696386 To: "Kevin Broadfoot" ;tag=as46c41ed7 Call-ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 CSeq: 751039122 BYE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 28 22:05:22] DEBUG[3810]: rtp.c:2993 bridge_native_loop: Oooh, got a hangup [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:17627 sip_set_rtp_peer: Sending reinvite on SIP '6600ed56-5253872c-6049974d@192.168.1.99' - It's audio soon redirected to IP 192.168.1.199 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 6600ed56-5253872c-6049974d@192.168.1.99 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.99, port 5060 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:6674 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.1.199 port 19666 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Feb 28 22:05:22] DEBUG[3810]: channel.c:2294 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:1716 initialize_initreq: Initializing already initialized SIP dialog 6600ed56-5253872c-6049974d@192.168.1.99 (presumably reinvite) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 35]: INVITE sip:099@192.168.1.99 SIP/2.0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5e542c9f;rport [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 55]: From: ;tag=as6322d2d3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 67]: To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 32]: Contact: [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 16]: CSeq: 103 INVITE [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56232 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Supported: replaces [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 240 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 37]: o=root 3806 3808 IN IP4 192.168.1.199 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=session [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.1.199 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 27]: m=audio 19666 RTP/AVP 0 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 10 [ 10]: a=ptime:20 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 192.168.1.99:5060: INVITE sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5e542c9f;rport Max-Forwards: 70 From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 Contact: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 103 INVITE User-Agent: Asterisk PBX SVN-trunk-r56232 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 240 v=0 o=root 3806 3808 IN IP4 192.168.1.199 s=session c=IN IP4 192.168.1.199 t=0 0 m=audio 19666 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #70 [Feb 28 22:05:22] DEBUG[3810]: channel.c:3971 ast_channel_bridge: Returning from native bridge, channels: SIP/099-081f0798, SIP/101-081fcfc0 [Feb 28 22:05:22] DEBUG[3810]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/101-081fcfc0' [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3603 sip_hangup: Hangup call SIP/101-081fcfc0, SIP callid 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3612 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3349 update_call_counter: Call to peer '101' removed from call limit 4 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081fcfc0 [Feb 28 22:05:22] DEBUG[3810]: rtp.c:1566 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 28 22:05:22] DEBUG[3810]: app_dial.c:1710 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 28 22:05:22] DEBUG[3810]: pbx.c:2289 __ast_pbx_run: Spawn extension (dlc_callforward,099,1) exited non-zero on 'SIP/099-081f0798' == Spawn extension (dlc_callforward, 099, 1) exited non-zero on 'SIP/099-081f0798' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"Kevin Broadfoot" <099>' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '099' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '099' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'dlc_callforward' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/099-081f0798' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081fcfc0' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Dial' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/099&SIP/101' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-28 22:05:12' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-28 22:05:13' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-28 22:05:22' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '10' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '9' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1172718312.0' [Feb 28 22:05:22] DEBUG[3810]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Feb 28 22:05:22] DEBUG[3810]: channel.c:1591 ast_hangup: Hanging up channel 'SIP/099-081f0798' [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3603 sip_hangup: Hangup call SIP/099-081f0798, SIP callid 6600ed56-5253872c-6049974d@192.168.1.99) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3612 sip_hangup: update_call_counter(099) - decrement call limit counter on hangup [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for incoming call [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3349 update_call_counter: Call from peer '099' removed from call limit 4 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099 Scheduling destruction of SIP dialog '6600ed56-5253872c-6049974d@192.168.1.99' in 32000 ms (Method: ACK) [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099-081f0798 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Feb 28 22:05:22] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK6f025fbc;rport Max-Forwards: 70 From: sip:101@192.168.1.199:5060;tag=as28504e61 To: Kevin Broadfoot ;tag=4535f1786e09faf Contact: Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 CSeq: 105 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 209 terminated --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #72 Extension Changed 101 new state Idle for Notify User 101 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 1 (Not in use) [Feb 28 22:05:22] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 101 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:22] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 Reliably Transmitting (no NAT) to 192.168.1.180:5060: NOTIFY sip:101@192.168.1.180 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK00ceac02;rport Max-Forwards: 70 From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Contact: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 107 NOTIFY User-Agent: Asterisk PBX SVN-trunk-r56232 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 208 confirmed --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #73 Extension Changed 099 new state InUse for Notify User 101 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:22] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 CSeq: 105 NOTIFY From: sip:101@192.168.1.199:5060;tag=as28504e61 To: Kevin Broadfoot ;tag=4535f1786e09faf Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK6f025fbc;rport Content-Length: 0 Contact: Kevin Broadfoot Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 105 NOTIFY [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:101@192.168.1.199:5060;tag=as28504e61 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=4535f1786e09faf [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK6f025fbc;rport [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Supported: replaces [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199 Their Tag 853eec464696386 Our tag: as46c41ed7 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: d86f893a19209a5f32391a395243cbb7@192.168.1.180 Their Tag 4535f1786e09faf Our tag: as28504e61 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #72 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on 'd86f893a19209a5f32391a395243cbb7@192.168.1.180' of Request 105: Match Found SIP Response message for INCOMING dialog NOTIFY arrived Really destroying SIP dialog '3c4ee31e765a31bc1065507c5abd3b63@192.168.1.199' Method: BYE <--- SIP read from 192.168.1.180:5060 ---> SIP/2.0 200 OK Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 CSeq: 107 NOTIFY From: sip:099@192.168.1.199:5060;tag=as153b45f2 To: Kevin Broadfoot ;tag=b34ef83a9a549de Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK00ceac02;rport Content-Length: 0 Contact: Kevin Broadfoot Supported: replaces User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 <-------------> [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 55]: Call-ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 16]: CSeq: 107 NOTIFY [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 47]: From: sip:099@192.168.1.199:5060;tag=as153b45f2 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 68]: To: Kevin Broadfoot ;tag=b34ef83a9a549de [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK00ceac02;rport [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 17]: Content-Length: 0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 48]: Contact: Kevin Broadfoot [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 19]: Supported: replaces [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 72]: User-Agent: Aastra 9133i/1.4.1.2000 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 351e555ff18e37612dce23dc01b01852@192.168.1.180 Their Tag b34ef83a9a549de Our tag: as153b45f2 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #73 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '351e555ff18e37612dce23dc01b01852@192.168.1.180' of Request 107: Match Found SIP Response message for INCOMING dialog NOTIFY arrived <--- SIP read from 192.168.1.99:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5e542c9f;rport From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 CSeq: 103 INVITE Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Content-Type: application/sdp Content-Length: 199 v=0 o=- 1172717511 1172717511 IN IP4 192.168.1.99 s=Polycom IP Phone c=IN IP4 192.168.1.99 t=0 0 m=audio 2248 RTP/AVP 0 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5e542c9f;rport [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 55]: From: ;tag=as6322d2d3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 67]: To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 16]: CSeq: 103 INVITE [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 29]: Content-Type: application/sdp [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 10 [ 19]: Content-Length: 199 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 11 [ 0]: [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 1 [ 45]: o=- 1172717511 1172717511 IN IP4 192.168.1.99 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 2 [ 18]: s=Polycom IP Phone [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 3 [ 21]: c=IN IP4 192.168.1.99 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 5 [ 26]: m=audio 2248 RTP/AVP 0 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 6 [ 10]: a=sendrecv [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 9 lines) --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2218 __sip_ack: Acked pending invite 103 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #70 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '6600ed56-5253872c-6049974d@192.168.1.99' of Request 103: Match Found [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:12287 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 192.168.1.99:2248 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.1.99:2248 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x4 (ulaw) [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:3305 update_call_counter: Updating call counter for incoming call [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/099 --- set_address_from_contact host '192.168.1.99' [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:8417 build_route: build_route: Retaining previous route: [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 6600ed56-5253872c-6049974d@192.168.1.99 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.99, port 5060 Transmitting (no NAT) to 192.168.1.99:5060: ACK sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK265dd108;rport Max-Forwards: 70 From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 Contact: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 103 ACK User-Agent: Asterisk PBX SVN-trunk-r56232 Content-Length: 0 --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:6050 reqprep: Strict routing enforced for session 6600ed56-5253872c-6049974d@192.168.1.99 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.99, port 5060 Reliably Transmitting (no NAT) to 192.168.1.99:5060: BYE sip:099@192.168.1.99 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5c332599;rport Max-Forwards: 70 From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 CSeq: 104 BYE User-Agent: Asterisk PBX SVN-trunk-r56232 Content-Length: 0 --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #74 Scheduling destruction of SIP dialog '6600ed56-5253872c-6049974d@192.168.1.99' in 32000 ms (Method: ACK) [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:428 do_state_change: Changing state for SIP/099 - state 2 (In use) [Feb 28 22:05:22] DEBUG[3810]: app_queue.c:568 changethread: Device 'SIP/099' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 28 22:05:22] DEBUG[3810]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 099 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 099 <--- SIP read from 192.168.1.99:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5c332599;rport From: ;tag=as6322d2d3 To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 CSeq: 104 BYE Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 Contact: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 Content-Length: 0 <-------------> [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.1.199:5060;branch=z9hG4bK5c332599;rport [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 2 [ 55]: From: ;tag=as6322d2d3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 3 [ 67]: To: "Kevin Broadfoot" ;tag=55B4E1A2-A2405CB3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 4 [ 13]: CSeq: 104 BYE [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 5 [ 48]: Call-ID: 6600ed56-5253872c-6049974d@192.168.1.99 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 6 [ 31]: Contact: [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_601-UA/1.6.5.0043 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 8 [ 17]: Content-Length: 0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4941 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = No match Their Call ID: 32e035ad3d09a51064af5d9a763be69f@192.168.1.199 Their Tag 670E9BA-37EB7A8B Our tag: as0ac4fbb0 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:4727 find_call: = Found Their Call ID: 6600ed56-5253872c-6049974d@192.168.1.99 Their Tag 55B4E1A2-A2405CB3 Our tag: as6322d2d3 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2223 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #74 [Feb 28 22:05:22] DEBUG[3810]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '6600ed56-5253872c-6049974d@192.168.1.99' of Request 104: Match Found Really destroying SIP dialog '6600ed56-5253872c-6049974d@192.168.1.99' Method: ACK *CLI> stop now