[Apr 11 14:18:23] Asterisk SVN-branch-1.4-r60137, Copyright (C) 1999 - 2006 Digium, Inc. and others. [Apr 11 14:18:23] Created by Mark Spencer [Apr 11 14:18:23] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Apr 11 14:18:23] This is free software, with components licensed under the GNU General Public [Apr 11 14:18:23] License version 2 and other licenses; you are welcome to redistribute it under [Apr 11 14:18:23] certain conditions. Type 'core show license' for details. [Apr 11 14:18:23] ========================================================================= [Apr 11 14:18:23] Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'CapPBX' (pid 21713)*CLI> core set verbose 9 Verbosity was 5 and is now 9 *CLI> core set debug 9 Core debug was 5 and is now 9 *CLI> sip set debug SIP Debugging enabled *CLI> [Apr 11 14:19:13] DEBUG[21724]: chan_iax2.c:7726 iax2_do_register: Allocate call number [Apr 11 14:19:13] DEBUG[21724]: chan_iax2.c:7732 iax2_do_register: Registration created on call 2 [Apr 11 14:19:23] <--- SIP read from 192.168.2.41:5060 ---> INVITE sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKd239179E72AC500 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: CSeq: 1 INVITE Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 249 v=0 o=- 1176315148 1176315148 IN IP4 192.168.2.41 s=Polycom IP Phone c=IN IP4 192.168.2.41 t=0 0 m=audio 2262 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 0: INVITE sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone SIP/2.0 (60) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKd239179E72AC500 (59) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=AE75D4FF-17BBB1A4 (59) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 3: To: (46) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 4: CSeq: 1 INVITE (14) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 (48) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 11: Max-Forwards: 70 (16) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 13: Content-Length: 249 (19) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 14: (0) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: o=- 1176315148 1176315148 IN IP4 192.168.2.41 (45) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: c=IN IP4 192.168.2.41 (21) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: m=audio 2262 RTP/AVP 0 8 18 101 (31) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 11 14:19:23] --- (14 headers 11 lines) --- [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to Off [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 418564eb-9bda91ed-2ce495aa@192.168.2.41 - INVITE (With RTP) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:1682 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:1690 parse_sip_options: Found SIP option: -100rel- [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:1696 parse_sip_options: Matched SIP option: 100rel [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:1690 parse_sip_options: Found SIP option: -replaces- [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:1696 parse_sip_options: Matched SIP option: replaces [Apr 11 14:19:23] Sending to 192.168.2.41 : 5060 (no NAT) [Apr 11 14:19:23] Using INVITE request as basis request - 418564eb-9bda91ed-2ce495aa@192.168.2.41 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to Off [Apr 11 14:19:23] <--- Reliably Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKd239179E72AC500;received=192.168.2.41 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as5daf95d4 Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2c52febc" Content-Length: 0 <------------> [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1 [Apr 11 14:19:23] Scheduling destruction of SIP dialog '418564eb-9bda91ed-2ce495aa@192.168.2.41' in 32000 ms (Method: INVITE) [Apr 11 14:19:23] Found user '2400' [Apr 11 14:19:23] <--- SIP read from 192.168.2.41:5060 ---> ACK sip:9XXXXXXXXXX@192.168.2.150:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKd239179E72AC500 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as5daf95d4 CSeq: 1 ACK Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 0: ACK sip:9XXXXXXXXXX@192.168.2.150:5060 SIP/2.0 (46) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKd239179E72AC500 (59) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=AE75D4FF-17BBB1A4 (59) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as5daf95d4 (61) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 4: CSeq: 1 ACK (11) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 (48) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 9: Max-Forwards: 70 (16) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:19:23] --- (11 headers 0 lines) --- [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4363 find_call: = Found Their Call ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Their Tag AE75D4FF-17BBB1A4 Our tag: as5daf95d4 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:14696 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:2091 __sip_ack: Stopping retransmission on '418564eb-9bda91ed-2ce495aa@192.168.2.41' of Response 1: Match Not Found [Apr 11 14:19:23] <--- SIP read from 192.168.2.41:5060 ---> INVITE sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK235aa36eAE8F4EA1 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: CSeq: 2 INVITE Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Supported: 100rel,replaces Allow-Events: talk,hold,conference Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="2c52febc", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="016c06b15a54afb6d062d1139c1d6806", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 249 v=0 o=- 1176315148 1176315148 IN IP4 192.168.2.41 s=Polycom IP Phone c=IN IP4 192.168.2.41 t=0 0 m=audio 2262 RTP/AVP 0 8 18 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 0: INVITE sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone SIP/2.0 (60) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK235aa36eAE8F4EA1 (60) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=AE75D4FF-17BBB1A4 (59) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 3: To: (46) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 4: CSeq: 2 INVITE (14) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 (48) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 11: Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="2c52febc", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="016c06b15a54afb6d062d1139c1d6806", algorithm=MD5 (192) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 12: Max-Forwards: 70 (16) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 13: Content-Type: application/sdp (29) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 14: Content-Length: 249 (19) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 15: (0) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: o=- 1176315148 1176315148 IN IP4 192.168.2.41 (45) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: c=IN IP4 192.168.2.41 (21) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: m=audio 2262 RTP/AVP 0 8 18 101 (31) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 11 14:19:23] --- (15 headers 11 lines) --- [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:4363 find_call: = Found Their Call ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Their Tag AE75D4FF-17BBB1A4 Our tag: as5daf95d4 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 11 14:19:23] Sending to 192.168.2.41 : 5060 (no NAT) [Apr 11 14:19:23] Using INVITE request as basis request - 418564eb-9bda91ed-2ce495aa@192.168.2.41 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to Off [Apr 11 14:19:23] Found user '2400' [Apr 11 14:19:23] Found RTP audio format 0 [Apr 11 14:19:23] Found RTP audio format 8 [Apr 11 14:19:23] Found RTP audio format 18 [Apr 11 14:19:23] Found RTP audio format 101 [Apr 11 14:19:23] Peer audio RTP is at port 192.168.2.41:2262 [Apr 11 14:19:23] Found description format PCMU for ID 0 [Apr 11 14:19:23] Found description format PCMA for ID 8 [Apr 11 14:19:23] Found description format G729 for ID 18 [Apr 11 14:19:23] Found description format telephone-event for ID 101 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:5134 process_sdp: T38 state changed to 0 on channel [Apr 11 14:19:23] Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Apr 11 14:19:23] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 11 14:19:23] Peer audio RTP is at port 192.168.2.41:2262 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:5214 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:13407 handle_request_invite: Checking SIP call limits for device 2400 [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:3005 update_call_counter: Updating call counter for incoming call [Apr 11 14:19:23] Looking for 9XXXXXXXXXX in sip-internal (domain 192.168.2.150) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:3807 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:3808 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:3809 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:3810 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:3833 sip_new: This channel will not be able to handle video. [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:7986 build_route: build_route: Contact hop: [Apr 11 14:19:23] list_route: hop: [Apr 11 14:19:23] DEBUG[21718]: chan_sip.c:13482 handle_request_invite: SIP/2400-0821b5c8: New call is still down.... Trying... [Apr 11 14:19:23] <--- Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK235aa36eAE8F4EA1;received=192.168.2.41 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 11 14:19:23] DEBUG[21718]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-0821b5c8 [Apr 11 14:19:23] DEBUG[21717]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [Apr 11 14:19:23] DEBUG[21717]: chan_sip.c:15307 sip_devicestate: Checking device state for peer 2400 [Apr 11 14:19:23] WARNING[21717]: chan_sip.c:16139 build_peer: Ignoring unknown option 'id' at line 0 of sip.conf! [Apr 11 14:19:23] WARNING[21717]: chan_sip.c:16139 build_peer: Ignoring unknown option 'name' at line 0 of sip.conf! [Apr 11 14:19:23] WARNING[21717]: chan_sip.c:16139 build_peer: Ignoring unknown option 'fullcontact' at line 0 of sip.conf! [Apr 11 14:19:23] WARNING[21717]: chan_sip.c:16139 build_peer: Ignoring unknown option 'regseconds' at line 0 of sip.conf! [Apr 11 14:19:23] WARNING[21717]: chan_sip.c:16139 build_peer: Ignoring unknown option 'ipaddr' at line 0 of sip.conf! [Apr 11 14:19:23] WARNING[21717]: chan_sip.c:16139 build_peer: Ignoring unknown option 'cancallforward' at line 0 of sip.conf! [Apr 11 14:19:23] DEBUG[21717]: chan_sip.c:7638 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.41:5060 for 3600 [Apr 11 14:19:23] DEBUG[21717]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [Apr 11 14:19:23] DEBUG[21734]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Apr 11 14:19:23] -- Executing [9XXXXXXXXXX@sip-internal:1] Set("SIP/2400-0821b5c8", "SPYGROUP=10001") in new stack [Apr 11 14:19:23] DEBUG[21734]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 11 14:19:23] -- Executing [9XXXXXXXXXX@sip-internal:2] Dial("SIP/2400-0821b5c8", "Zap/g1/9XXXXXXXXXX") in new stack [Apr 11 14:19:23] DEBUG[21734]: chan_zap.c:7799 zt_request: Using channel 1 [Apr 11 14:19:23] DEBUG[21734]: rtp.c:1555 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything [Apr 11 14:19:23] DEBUG[21734]: channel.c:3323 ast_channel_inherit_variables: Not copying variable STACK-sip-internal-9XXXXXXXXXX-2. [Apr 11 14:19:23] DEBUG[21734]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SPYGROUP. [Apr 11 14:19:23] DEBUG[21734]: channel.c:3323 ast_channel_inherit_variables: Not copying variable STACK-sip-internal-9XXXXXXXXXX-1. [Apr 11 14:19:23] DEBUG[21734]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 11 14:19:23] DEBUG[21734]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 11 14:19:23] DEBUG[21734]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 11 14:19:23] DEBUG[21734]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 11 14:19:23] DEBUG[21734]: chan_zap.c:1942 zt_call: Dialing '9XXXXXXXXXX' [Apr 11 14:19:23] DEBUG[21734]: chan_zap.c:2018 zt_call: Deferring dialing... [Apr 11 14:19:23] DEBUG[21735]: app_queue.c:546 changethread: Device 'SIP/2400' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 11 14:19:23] DEBUG[21734]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Apr 11 14:19:23] DEBUG[21717]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Apr 11 14:19:23] DEBUG[21717]: channel.c:1031 channel_find_locked: Avoiding initial deadlock for channel '0x82210e8' [Apr 11 14:19:23] -- Called g1/9XXXXXXXXXX [Apr 11 14:19:23] DEBUG[21717]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Apr 11 14:19:23] DEBUG[21736]: app_queue.c:546 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 11 14:19:24] DEBUG[21734]: chan_zap.c:4493 __zt_exception: Exception on 14, channel 1 [Apr 11 14:19:24] DEBUG[21734]: chan_zap.c:3614 zt_handle_event: Got event Hook Transition Complete(12) on channel 1 (index 0) [Apr 11 14:19:24] -- Message count requested for mailbox 2400@CapPBX but voicemail not loaded. [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 11 14:19:24] Scheduling destruction of SIP dialog '3c5df30c395cc4b556dca5d918242936@192.168.2.150' in 32000 ms (Method: NOTIFY) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 0: NOTIFY sip:2400@192.168.2.41 SIP/2.0 (36) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK41564b88;rport (64) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as4c268fdd (60) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 3: To: (27) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 4: Contact: (37) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 3c5df30c395cc4b556dca5d918242936@192.168.2.150 (55) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 9: Event: message-summary (22) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 11: Content-Length: 93 (18) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 12: (0) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: Messages-Waiting: no (20) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: Message-Account: sip:asterisk@192.168.2.150 (43) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4607 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Apr 11 14:19:24] Reliably Transmitting (no NAT) to 192.168.2.41:5060: NOTIFY sip:2400@192.168.2.41 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK41564b88;rport From: "asterisk" ;tag=as4c268fdd To: Contact: Call-ID: 3c5df30c395cc4b556dca5d918242936@192.168.2.150 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 93 Messages-Waiting: no Message-Account: sip:asterisk@192.168.2.150 Voice-Message: 0/0 (0/0) --- [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #5 [Apr 11 14:19:24] <--- SIP read from 192.168.2.41:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK41564b88;rport From: "asterisk" ;tag=as4c268fdd To: ;tag=19DC10AC-7C9C1B95 CSeq: 102 NOTIFY Call-ID: 3c5df30c395cc4b556dca5d918242936@192.168.2.150 Contact: Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Content-Length: 0 <-------------> [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK41564b88;rport (64) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as4c268fdd (60) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=19DC10AC-7C9C1B95 (49) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 4: CSeq: 102 NOTIFY (16) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 3c5df30c395cc4b556dca5d918242936@192.168.2.150 (55) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 7: Event: message-summary (22) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 9: Content-Length: 0 (17) [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 10: (0) [Apr 11 14:19:24] --- (10 headers 0 lines) --- [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:4363 find_call: = Found Their Call ID: 3c5df30c395cc4b556dca5d918242936@192.168.2.150 Their Tag Our tag: as4c268fdd [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5 [Apr 11 14:19:24] DEBUG[21718]: chan_sip.c:2091 __sip_ack: Stopping retransmission on '3c5df30c395cc4b556dca5d918242936@192.168.2.150' of Request 102: Match Not Found [Apr 11 14:19:24] Really destroying SIP dialog '3c5df30c395cc4b556dca5d918242936@192.168.2.150' Method: NOTIFY [Apr 11 14:19:27] DEBUG[21734]: chan_zap.c:4493 __zt_exception: Exception on 14, channel 1 [Apr 11 14:19:27] DEBUG[21734]: chan_zap.c:3614 zt_handle_event: Got event Dial Complete(9) on channel 1 (index 0) [Apr 11 14:19:27] DEBUG[21734]: chan_zap.c:1433 zt_enable_ec: Enabled echo cancellation on channel 1 [Apr 11 14:19:27] DEBUG[21734]: chan_zap.c:3689 zt_handle_event: Done dialing, but waiting for progress detection before doing more... [Apr 11 14:19:27] DEBUG[21734]: chan_sip.c:6426 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 11 14:19:27] DEBUG[21734]: chan_sip.c:6194 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 11 14:19:27] DEBUG[21734]: chan_sip.c:6195 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 11 14:19:27] Audio is at 192.168.2.150 port 17514 [Apr 11 14:19:27] Adding codec 0x4 (ulaw) to SDP [Apr 11 14:19:27] Adding non-codec 0x1 (telephone-event) to SDP [Apr 11 14:19:27] DEBUG[21734]: chan_sip.c:6326 add_sdp: -- Done with adding codecs to SDP [Apr 11 14:19:27] DEBUG[21734]: channel.c:2394 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Apr 11 14:19:27] DEBUG[21734]: chan_sip.c:6371 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 11 14:19:27] <--- Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK235aa36eAE8F4EA1;received=192.168.2.41 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as6b68d668 Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 242 v=0 o=root 21713 21713 IN IP4 192.168.2.150 s=session c=IN IP4 192.168.2.150 t=0 0 m=audio 17514 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 <------------> [Apr 11 14:19:27] DEBUG[21734]: rtp.c:2705 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 11 14:19:27] DEBUG[21734]: rtp.c:2722 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 11 14:19:27] -- Zap/1-1 is ringing [Apr 11 14:19:27] DEBUG[21734]: rtp.c:1480 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Apr 11 14:19:27] <--- Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK235aa36eAE8F4EA1;received=192.168.2.41 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as6b68d668 Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 11 14:19:29] DEBUG[21734]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Apr 11 14:19:34] DEBUG[21734]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Apr 11 14:19:34] -- Zap/1-1 answered SIP/2400-0821b5c8 [Apr 11 14:19:34] DEBUG[21734]: rtp.c:1480 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Apr 11 14:19:34] DEBUG[21734]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-0821b5c8 [Apr 11 14:19:34] DEBUG[21734]: chan_sip.c:3465 sip_answer: SIP answering channel: SIP/2400-0821b5c8 [Apr 11 14:19:34] DEBUG[21734]: chan_sip.c:6426 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 11 14:19:34] DEBUG[21734]: chan_sip.c:6194 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 11 14:19:34] DEBUG[21734]: chan_sip.c:6195 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 11 14:19:34] Audio is at 192.168.2.150 port 17514 [Apr 11 14:19:34] Adding codec 0x4 (ulaw) to SDP [Apr 11 14:19:34] Adding non-codec 0x1 (telephone-event) to SDP [Apr 11 14:19:34] DEBUG[21734]: chan_sip.c:6326 add_sdp: -- Done with adding codecs to SDP [Apr 11 14:19:34] DEBUG[21734]: channel.c:2394 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Apr 11 14:19:34] DEBUG[21734]: chan_sip.c:6371 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 11 14:19:34] <--- Reliably Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK235aa36eAE8F4EA1;received=192.168.2.41 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as6b68d668 Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 242 v=0 o=root 21713 21714 IN IP4 192.168.2.150 s=session c=IN IP4 192.168.2.150 t=0 0 m=audio 17514 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 <------------> [Apr 11 14:19:34] DEBUG[21734]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7 [Apr 11 14:19:34] WARNING[21734]: cdr.c:482 ast_cdr_merge: CDR start disagreement for SIP/2400-0821b5c8 [Apr 11 14:19:34] DEBUG[21717]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Apr 11 14:19:34] DEBUG[21717]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Apr 11 14:19:34] DEBUG[21717]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [Apr 11 14:19:34] DEBUG[21717]: chan_sip.c:15307 sip_devicestate: Checking device state for peer 2400 [Apr 11 14:19:34] DEBUG[21717]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [Apr 11 14:19:34] DEBUG[21740]: app_queue.c:546 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 11 14:19:34] DEBUG[21741]: app_queue.c:546 changethread: Device 'SIP/2400' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 11 14:19:34] DEBUG[21734]: rtp.c:2722 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 11 14:19:34] <--- SIP read from 192.168.2.41:5060 ---> ACK sip:9XXXXXXXXXX@192.168.2.150 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK9c1fc3e7518DB2B6 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as6b68d668 CSeq: 2 ACK Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="2c52febc", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="016c06b15a54afb6d062d1139c1d6806", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 0: ACK sip:9XXXXXXXXXX@192.168.2.150 SIP/2.0 (41) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK9c1fc3e7518DB2B6 (60) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=AE75D4FF-17BBB1A4 (59) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as6b68d668 (61) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 4: CSeq: 2 ACK (11) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 (48) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 9: Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="2c52febc", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="016c06b15a54afb6d062d1139c1d6806", algorithm=MD5 (192) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 10: Max-Forwards: 70 (16) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 11: Content-Length: 0 (17) [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 12: (0) [Apr 11 14:19:34] --- (12 headers 0 lines) --- [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:4363 find_call: = Found Their Call ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Their Tag AE75D4FF-17BBB1A4 Our tag: as6b68d668 [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:14696 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7 [Apr 11 14:19:34] DEBUG[21718]: chan_sip.c:2091 __sip_ack: Stopping retransmission on '418564eb-9bda91ed-2ce495aa@192.168.2.41' of Response 2: Match Not Found [Apr 11 14:19:37] <--- SIP read from 192.168.2.41:5060 ---> BYE sip:9XXXXXXXXXX@192.168.2.150 SIP/2.0 Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKdf6d8cc9ADF2CB10 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as6b68d668 CSeq: 3 BYE Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="2c52febc", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="1970abbfad0657321505d917c47d3b9d", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 0: BYE sip:9XXXXXXXXXX@192.168.2.150 SIP/2.0 (41) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKdf6d8cc9ADF2CB10 (60) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=AE75D4FF-17BBB1A4 (59) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as6b68d668 (61) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 4: CSeq: 3 BYE (11) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 (48) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 8: Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="2c52febc", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="1970abbfad0657321505d917c47d3b9d", algorithm=MD5 (192) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 9: Max-Forwards: 70 (16) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:19:37] --- (11 headers 0 lines) --- [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:4363 find_call: = Found Their Call ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 Their Tag AE75D4FF-17BBB1A4 Our tag: as6b68d668 [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:14696 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 11 14:19:37] Sending to 192.168.2.41 : 5060 (no NAT) [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:1635 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 418564eb-9bda91ed-2ce495aa@192.168.2.41 [Apr 11 14:19:37] DEBUG[21718]: chan_sip.c:14253 handle_request_bye: Received bye, issuing owner hangup [Apr 11 14:19:37] <--- Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKdf6d8cc9ADF2CB10;received=192.168.2.41 From: "2400" ;tag=AE75D4FF-17BBB1A4 To: ;tag=as6b68d668 Call-ID: 418564eb-9bda91ed-2ce495aa@192.168.2.41 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 11 14:19:37] DEBUG[21734]: channel.c:3828 ast_generic_bridge: Didn't get a frame from channel: SIP/2400-0821b5c8 [Apr 11 14:19:37] DEBUG[21734]: channel.c:4146 ast_channel_bridge: Bridge stops bridging channels SIP/2400-0821b5c8 and Zap/1-1 [Apr 11 14:19:37] DEBUG[21734]: channel.c:1698 ast_hangup: Hanging up channel 'Zap/1-1' [Apr 11 14:19:37] DEBUG[21734]: chan_zap.c:2410 zt_hangup: zt_hangup(Zap/1-1) [Apr 11 14:19:37] DEBUG[21734]: chan_zap.c:2443 zt_hangup: Hangup: channel: 1 index = 0, normal = 14, callwait = -1, thirdcall = -1 [Apr 11 14:19:37] DEBUG[21734]: chan_zap.c:1465 zt_disable_ec: disabled echo cancellation on channel 1 [Apr 11 14:19:37] DEBUG[21734]: chan_zap.c:2870 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1 [Apr 11 14:19:37] DEBUG[21734]: chan_zap.c:1402 update_conf: Updated conferencing on 1, with 0 conference users [Apr 11 14:19:37] -- Hungup 'Zap/1-1' [Apr 11 14:19:37] DEBUG[21734]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Apr 11 14:19:37] DEBUG[21734]: rtp.c:1480 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 11 14:19:37] DEBUG[21734]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 11 14:19:37] DEBUG[21734]: pbx.c:2393 __ast_pbx_run: Spawn extension (sip-internal,9XXXXXXXXXX,2) exited non-zero on 'SIP/2400-0821b5c8' [Apr 11 14:19:37] == Spawn extension (sip-internal, 9XXXXXXXXXX, 2) exited non-zero on 'SIP/2400-0821b5c8' [Apr 11 14:19:37] DEBUG[21734]: channel.c:1698 ast_hangup: Hanging up channel 'SIP/2400-0821b5c8' [Apr 11 14:19:37] DEBUG[21734]: chan_sip.c:3314 sip_hangup: Hangup call SIP/2400-0821b5c8, SIP callid 418564eb-9bda91ed-2ce495aa@192.168.2.41) [Apr 11 14:19:37] DEBUG[21734]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-0821b5c8 [Apr 11 14:19:37] DEBUG[21717]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Apr 11 14:19:37] DEBUG[21717]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown) [Apr 11 14:19:37] DEBUG[21717]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [Apr 11 14:19:37] DEBUG[21717]: chan_sip.c:15307 sip_devicestate: Checking device state for peer 2400 [Apr 11 14:19:37] DEBUG[21717]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [Apr 11 14:19:37] DEBUG[21742]: app_queue.c:546 changethread: Device 'Zap/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 11 14:19:37] DEBUG[21743]: app_queue.c:546 changethread: Device 'SIP/2400' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 11 14:19:38] Really destroying SIP dialog '418564eb-9bda91ed-2ce495aa@192.168.2.41' Method: BYE stop now [Apr 11 14:20:02] Beginning asterisk shutdown.... [Apr 11 14:20:02] Executing last minute cleanups [Apr 11 14:20:02] == Destroying musiconhold processes [Apr 11 14:20:02] Asterisk cleanly ending (0). [Apr 11 14:20:02] DEBUG[21713]: asterisk.c:1276 quit_handler: Asterisk ending (0).