[Apr 11 14:43:35] Asterisk SVN-branch-1.4-r60137, Copyright (C) 1999 - 2006 Digium, Inc. and others. [Apr 11 14:43:35] Created by Mark Spencer [Apr 11 14:43:35] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Apr 11 14:43:35] This is free software, with components licensed under the GNU General Public [Apr 11 14:43:35] License version 2 and other licenses; you are welcome to redistribute it under [Apr 11 14:43:35] certain conditions. Type 'core show license' for details. [Apr 11 14:43:35] ========================================================================= [Apr 11 14:43:35] Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'CapPBX' (pid 21785)*CLI> core set debug 09 Core debug was 5 and is now 9 *CLI> core set verbose 9 Verbosity was 5 and is now 9 *CLI> sip set debug SIP Debugging enabled *CLI> [Apr 11 14:44:15] <--- 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=z9hG4bK82035b23A2138702 From: "2400" ;tag=69BC0C19-A1FD5046 To: CSeq: 1 INVITE Call-ID: e0d141e5-75ab4cb7-1ed315bc@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=- 1176316640 1176316640 IN IP4 192.168.2.41 s=Polycom IP Phone c=IN IP4 192.168.2.41 t=0 0 m=audio 2268 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:44:15] DEBUG[21790]: 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:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK82035b23A2138702 (60) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: (46) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: CSeq: 1 INVITE (14) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:44:15] DEBUG[21790]: 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:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: Max-Forwards: 70 (16) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 13: Content-Length: 249 (19) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 14: (0) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: o=- 1176316640 1176316640 IN IP4 192.168.2.41 (45) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: c=IN IP4 192.168.2.41 (21) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: m=audio 2268 RTP/AVP 0 8 18 101 (31) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 11 14:44:15] --- (14 headers 11 lines) --- [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to Off [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 - INVITE (With RTP) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:1682 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:1690 parse_sip_options: Found SIP option: -100rel- [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:1696 parse_sip_options: Matched SIP option: 100rel [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:1690 parse_sip_options: Found SIP option: -replaces- [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:1696 parse_sip_options: Matched SIP option: replaces [Apr 11 14:44:15] Sending to 192.168.2.41 : 5060 (no NAT) [Apr 11 14:44:15] Using INVITE request as basis request - e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to Off [Apr 11 14:44:15] <--- 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=z9hG4bK82035b23A2138702;received=192.168.2.41 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as607cda8a Call-ID: e0d141e5-75ab4cb7-1ed315bc@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="58f39b7f" Content-Length: 0 <------------> [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 407 Proxy Authentication Required (41) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK82035b23A2138702;received=192.168.2.41 (82) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as607cda8a (61) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: CSeq: 1 INVITE (14) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: Supported: replaces (19) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="58f39b7f" (76) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1 [Apr 11 14:44:15] Scheduling destruction of SIP dialog 'e0d141e5-75ab4cb7-1ed315bc@192.168.2.41' in 32000 ms (Method: INVITE) [Apr 11 14:44:15] Found user '2400' [Apr 11 14:44:15] <--- 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=z9hG4bK82035b23A2138702 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as607cda8a CSeq: 1 ACK Call-ID: e0d141e5-75ab4cb7-1ed315bc@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:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: ACK sip:9XXXXXXXXXX@192.168.2.150:5060 SIP/2.0 (46) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK82035b23A2138702 (60) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as607cda8a (61) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: CSeq: 1 ACK (11) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:44:15] DEBUG[21790]: 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:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Max-Forwards: 70 (16) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:44:15] --- (11 headers 0 lines) --- [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4363 find_call: = Found Their Call ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 Their Tag 69BC0C19-A1FD5046 Our tag: as607cda8a [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:14696 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1 [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:2091 __sip_ack: Stopping retransmission on 'e0d141e5-75ab4cb7-1ed315bc@192.168.2.41' of Response 1: Match Not Found [Apr 11 14:44:15] <--- 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=z9hG4bKe1b34520A2DE148B From: "2400" ;tag=69BC0C19-A1FD5046 To: CSeq: 2 INVITE Call-ID: e0d141e5-75ab4cb7-1ed315bc@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="58f39b7f", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="3fdb60a2d36689f08197a21735035eaf", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 249 v=0 o=- 1176316640 1176316640 IN IP4 192.168.2.41 s=Polycom IP Phone c=IN IP4 192.168.2.41 t=0 0 m=audio 2268 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:44:15] DEBUG[21790]: 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:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKe1b34520A2DE148B (60) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: (46) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: CSeq: 2 INVITE (14) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:44:15] DEBUG[21790]: 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:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Supported: 100rel,replaces (26) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="58f39b7f", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="3fdb60a2d36689f08197a21735035eaf", algorithm=MD5 (192) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 12: Max-Forwards: 70 (16) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 13: Content-Type: application/sdp (29) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 14: Content-Length: 249 (19) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 15: (0) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: o=- 1176316640 1176316640 IN IP4 192.168.2.41 (45) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: s=Polycom IP Phone (18) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: c=IN IP4 192.168.2.41 (21) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: m=audio 2268 RTP/AVP 0 8 18 101 (31) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 11 14:44:15] --- (15 headers 11 lines) --- [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4363 find_call: = Found Their Call ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 Their Tag 69BC0C19-A1FD5046 Our tag: as607cda8a [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:14696 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 11 14:44:15] Sending to 192.168.2.41 : 5060 (no NAT) [Apr 11 14:44:15] Using INVITE request as basis request - e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:2577 do_setnat: Setting NAT on RTP to Off [Apr 11 14:44:15] Found user '2400' [Apr 11 14:44:15] Found RTP audio format 0 [Apr 11 14:44:15] Found RTP audio format 8 [Apr 11 14:44:15] Found RTP audio format 18 [Apr 11 14:44:15] Found RTP audio format 101 [Apr 11 14:44:15] Peer audio RTP is at port 192.168.2.41:2268 [Apr 11 14:44:15] Found description format PCMU for ID 0 [Apr 11 14:44:15] Found description format PCMA for ID 8 [Apr 11 14:44:15] Found description format G729 for ID 18 [Apr 11 14:44:15] Found description format telephone-event for ID 101 [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:5134 process_sdp: T38 state changed to 0 on channel [Apr 11 14:44:15] Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Apr 11 14:44:15] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 11 14:44:15] Peer audio RTP is at port 192.168.2.41:2268 [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:5214 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:13407 handle_request_invite: Checking SIP call limits for device 2400 [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:3005 update_call_counter: Updating call counter for incoming call [Apr 11 14:44:15] Looking for 9XXXXXXXXXX in sip-internal (domain 192.168.2.150) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:3807 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:3808 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:3809 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:3810 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:3833 sip_new: This channel will not be able to handle video. [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:7986 build_route: build_route: Contact hop: [Apr 11 14:44:15] list_route: hop: [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:13482 handle_request_invite: SIP/2400-0822af70: New call is still down.... Trying... [Apr 11 14:44:15] <--- Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 From: "2400" ;tag=69BC0C19-A1FD5046 To: Call-ID: e0d141e5-75ab4cb7-1ed315bc@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:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 100 Trying (18) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 (82) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: (46) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: CSeq: 2 INVITE (14) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: Supported: replaces (19) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Contact: (40) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:44:15] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:44:15] DEBUG[21790]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-0822af70 [Apr 11 14:44:15] DEBUG[21789]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [Apr 11 14:44:15] DEBUG[21789]: chan_sip.c:15307 sip_devicestate: Checking device state for peer 2400 [Apr 11 14:44:15] DEBUG[21806]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Apr 11 14:44:15] -- Executing [9XXXXXXXXXX@sip-internal:1] Set("SIP/2400-0822af70", "SPYGROUP=10001") in new stack [Apr 11 14:44:15] DEBUG[21806]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 11 14:44:15] -- Executing [9XXXXXXXXXX@sip-internal:2] Dial("SIP/2400-0822af70", "Zap/g1/9XXXXXXXXXX") in new stack [Apr 11 14:44:15] DEBUG[21806]: chan_zap.c:7799 zt_request: Using channel 1 [Apr 11 14:44:15] WARNING[21789]: chan_sip.c:16139 build_peer: Ignoring unknown option 'id' at line 0 of sip.conf! [Apr 11 14:44:15] WARNING[21789]: chan_sip.c:16139 build_peer: Ignoring unknown option 'name' at line 0 of sip.conf! [Apr 11 14:44:15] DEBUG[21806]: rtp.c:1555 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything [Apr 11 14:44:15] WARNING[21789]: chan_sip.c:16139 build_peer: Ignoring unknown option 'fullcontact' at line 0 of sip.conf! [Apr 11 14:44:15] DEBUG[21806]: channel.c:3323 ast_channel_inherit_variables: Not copying variable STACK-sip-internal-9XXXXXXXXXX-2. [Apr 11 14:44:15] WARNING[21789]: chan_sip.c:16139 build_peer: Ignoring unknown option 'regseconds' at line 0 of sip.conf! [Apr 11 14:44:15] DEBUG[21806]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SPYGROUP. [Apr 11 14:44:15] WARNING[21789]: chan_sip.c:16139 build_peer: Ignoring unknown option 'ipaddr' at line 0 of sip.conf! [Apr 11 14:44:15] DEBUG[21806]: channel.c:3323 ast_channel_inherit_variables: Not copying variable STACK-sip-internal-9XXXXXXXXXX-1. [Apr 11 14:44:15] WARNING[21789]: chan_sip.c:16139 build_peer: Ignoring unknown option 'cancallforward' at line 0 of sip.conf! [Apr 11 14:44:15] DEBUG[21806]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 11 14:44:15] DEBUG[21789]: 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:44:15] DEBUG[21789]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [Apr 11 14:44:15] DEBUG[21806]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 11 14:44:15] DEBUG[21806]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 11 14:44:15] DEBUG[21807]: 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:44:15] DEBUG[21806]: channel.c:3323 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 11 14:44:15] DEBUG[21806]: chan_zap.c:1942 zt_call: Dialing '9XXXXXXXXXX' [Apr 11 14:44:15] DEBUG[21806]: chan_zap.c:2018 zt_call: Deferring dialing... [Apr 11 14:44:15] DEBUG[21806]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Apr 11 14:44:15] -- Called g1/9XXXXXXXXXX [Apr 11 14:44:15] DEBUG[21789]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Apr 11 14:44:15] DEBUG[21789]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Apr 11 14:44:15] DEBUG[21808]: 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:44:16] DEBUG[21806]: chan_zap.c:4493 __zt_exception: Exception on 14, channel 1 [Apr 11 14:44:16] DEBUG[21806]: chan_zap.c:3614 zt_handle_event: Got event Hook Transition Complete(12) on channel 1 (index 0) [Apr 11 14:44:16] -- Message count requested for mailbox 2400@CapPBX but voicemail not loaded. [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Apr 11 14:44:16] Scheduling destruction of SIP dialog '02124d49099f83921726597f5f7afc94@192.168.2.150' in 32000 ms (Method: NOTIFY) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: NOTIFY sip:2400@192.168.2.41 SIP/2.0 (36) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK72db147a;rport (64) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as02ae7efa (60) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: (27) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: Contact: (37) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 02124d49099f83921726597f5f7afc94@192.168.2.150 (55) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Event: message-summary (22) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: Content-Length: 93 (18) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 12: (0) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: Messages-Waiting: no (20) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: Message-Account: sip:asterisk@192.168.2.150 (43) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Apr 11 14:44:16] 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=z9hG4bK72db147a;rport From: "asterisk" ;tag=as02ae7efa To: Contact: Call-ID: 02124d49099f83921726597f5f7afc94@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:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: NOTIFY sip:2400@192.168.2.41 SIP/2.0 (36) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK72db147a;rport (64) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as02ae7efa (60) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: (27) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: Contact: (37) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 02124d49099f83921726597f5f7afc94@192.168.2.150 (55) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Event: message-summary (22) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: Content-Length: 93 (18) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 12: (0) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: Messages-Waiting: no (20) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: Message-Account: sip:asterisk@192.168.2.150 (43) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4607 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #5 [Apr 11 14:44:16] <--- SIP read from 192.168.2.41:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK72db147a;rport From: "asterisk" ;tag=as02ae7efa To: ;tag=BE721E8E-E61A269F CSeq: 102 NOTIFY Call-ID: 02124d49099f83921726597f5f7afc94@192.168.2.150 Contact: Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Content-Length: 0 <-------------> [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.150:5060;branch=z9hG4bK72db147a;rport (64) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "asterisk" ;tag=as02ae7efa (60) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=BE721E8E-E61A269F (49) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: CSeq: 102 NOTIFY (16) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: 02124d49099f83921726597f5f7afc94@192.168.2.150 (55) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 7: Event: message-summary (22) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Content-Length: 0 (17) [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: (0) [Apr 11 14:44:16] --- (10 headers 0 lines) --- [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:4363 find_call: = Found Their Call ID: 02124d49099f83921726597f5f7afc94@192.168.2.150 Their Tag Our tag: as02ae7efa [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5 [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:2091 __sip_ack: Stopping retransmission on '02124d49099f83921726597f5f7afc94@192.168.2.150' of Request 102: Match Not Found [Apr 11 14:44:16] Really destroying SIP dialog '02124d49099f83921726597f5f7afc94@192.168.2.150' Method: NOTIFY [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:10732 sip_dump_history: ---------- SIP HISTORY for '02124d49099f83921726597f5f7afc94@192.168.2.150' [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:10736 sip_dump_history: * SIP Call [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 001. SchedDestroy 32000 ms [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 002. TxReqRel NOTIFY / 102 NOTIFY - -UNKNOWN- [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 003. Rx SIP/2.0 / 102 NOTIFY / 200 OK [Apr 11 14:44:16] DEBUG[21790]: chan_sip.c:10742 sip_dump_history: ---------- END SIP HISTORY for '02124d49099f83921726597f5f7afc94@192.168.2.150' [Apr 11 14:44:18] DEBUG[21806]: chan_zap.c:4493 __zt_exception: Exception on 14, channel 1 [Apr 11 14:44:18] DEBUG[21806]: chan_zap.c:3614 zt_handle_event: Got event Dial Complete(9) on channel 1 (index 0) [Apr 11 14:44:18] DEBUG[21806]: chan_zap.c:1433 zt_enable_ec: Enabled echo cancellation on channel 1 [Apr 11 14:44:18] DEBUG[21806]: chan_zap.c:3689 zt_handle_event: Done dialing, but waiting for progress detection before doing more... [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:6426 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:6194 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:6195 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 11 14:44:18] Audio is at 192.168.2.150 port 14604 [Apr 11 14:44:18] Adding codec 0x4 (ulaw) to SDP [Apr 11 14:44:18] Adding non-codec 0x1 (telephone-event) to SDP [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:6326 add_sdp: -- Done with adding codecs to SDP [Apr 11 14:44:18] DEBUG[21806]: channel.c:2394 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:6371 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 11 14:44:18] <--- 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=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as45393239 Call-ID: e0d141e5-75ab4cb7-1ed315bc@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 21785 21785 IN IP4 192.168.2.150 s=session c=IN IP4 192.168.2.150 t=0 0 m=audio 14604 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:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 (82) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as45393239 (61) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 4: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 5: CSeq: 2 INVITE (14) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 8: Supported: replaces (19) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 9: Contact: (40) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 10: Content-Type: application/sdp (29) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 11: Content-Length: 242 (19) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 12: (0) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: o=root 21785 21785 IN IP4 192.168.2.150 (39) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: s=session (9) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: c=IN IP4 192.168.2.150 (22) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: m=audio 14604 RTP/AVP 0 101 (27) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=fmtp:101 0-16 (15) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=silenceSupp:off - - - - (25) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=ptime:20 (10) [Apr 11 14:44:18] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 11 14:44:18] DEBUG[21806]: rtp.c:2705 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 11 14:44:18] DEBUG[21806]: rtp.c:2722 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 11 14:44:19] -- Zap/1-1 is ringing [Apr 11 14:44:19] DEBUG[21806]: rtp.c:1480 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Apr 11 14:44:19] <--- Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as45393239 Call-ID: e0d141e5-75ab4cb7-1ed315bc@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:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 (82) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as45393239 (61) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 4: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 5: CSeq: 2 INVITE (14) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 8: Supported: replaces (19) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 9: Contact: (40) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:44:19] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:44:22] DEBUG[21806]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [Apr 11 14:44:25] DEBUG[21796]: chan_iax2.c:7726 iax2_do_register: Allocate call number [Apr 11 14:44:25] DEBUG[21796]: chan_iax2.c:7732 iax2_do_register: Registration created on call 2 [Apr 11 14:44:26] DEBUG[21806]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Apr 11 14:44:26] -- Zap/1-1 answered SIP/2400-0822af70 [Apr 11 14:44:26] DEBUG[21789]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Apr 11 14:44:26] DEBUG[21806]: rtp.c:1480 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Apr 11 14:44:26] DEBUG[21789]: channel.c:1031 channel_find_locked: Avoiding initial deadlock for channel '0x8232ee8' [Apr 11 14:44:26] DEBUG[21806]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-0822af70 [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:3465 sip_answer: SIP answering channel: SIP/2400-0822af70 [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:6426 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:6194 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:6195 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 11 14:44:26] Audio is at 192.168.2.150 port 14604 [Apr 11 14:44:26] Adding codec 0x4 (ulaw) to SDP [Apr 11 14:44:26] Adding non-codec 0x1 (telephone-event) to SDP [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:6326 add_sdp: -- Done with adding codecs to SDP [Apr 11 14:44:26] DEBUG[21806]: channel.c:2394 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:6371 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 11 14:44:26] <--- 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=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as45393239 Call-ID: e0d141e5-75ab4cb7-1ed315bc@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 21785 21786 IN IP4 192.168.2.150 s=session c=IN IP4 192.168.2.150 t=0 0 m=audio 14604 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:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKe1b34520A2DE148B;received=192.168.2.41 (82) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as45393239 (61) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 4: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 5: CSeq: 2 INVITE (14) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 8: Supported: replaces (19) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 9: Contact: (40) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 10: Content-Type: application/sdp (29) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 11: Content-Length: 242 (19) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4575 parse_request: Header 12: (0) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: v=0 (3) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: o=root 21785 21786 IN IP4 192.168.2.150 (39) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: s=session (9) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: c=IN IP4 192.168.2.150 (22) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: t=0 0 (5) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: m=audio 14604 RTP/AVP 0 101 (27) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=fmtp:101 0-16 (15) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=silenceSupp:off - - - - (25) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=ptime:20 (10) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:4607 parse_request: Line: a=sendrecv (10) [Apr 11 14:44:26] DEBUG[21806]: chan_sip.c:1977 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7 [Apr 11 14:44:26] WARNING[21806]: cdr.c:482 ast_cdr_merge: CDR start disagreement for SIP/2400-0822af70 [Apr 11 14:44:26] DEBUG[21789]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Apr 11 14:44:26] DEBUG[21789]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [Apr 11 14:44:26] DEBUG[21789]: chan_sip.c:15307 sip_devicestate: Checking device state for peer 2400 [Apr 11 14:44:26] DEBUG[21789]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [Apr 11 14:44:26] DEBUG[21809]: 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:44:26] DEBUG[21810]: 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:44:26] DEBUG[21806]: rtp.c:2722 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 11 14:44:26] <--- 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=z9hG4bKce38d41984CFDA8 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as45393239 CSeq: 2 ACK Call-ID: e0d141e5-75ab4cb7-1ed315bc@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="58f39b7f", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="3fdb60a2d36689f08197a21735035eaf", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: ACK sip:9XXXXXXXXXX@192.168.2.150 SIP/2.0 (41) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bKce38d41984CFDA8 (59) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as45393239 (61) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: CSeq: 2 ACK (11) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:44:26] DEBUG[21790]: 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:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="58f39b7f", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="3fdb60a2d36689f08197a21735035eaf", algorithm=MD5 (192) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Max-Forwards: 70 (16) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: Content-Length: 0 (17) [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 12: (0) [Apr 11 14:44:26] --- (12 headers 0 lines) --- [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:4363 find_call: = Found Their Call ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 Their Tag 69BC0C19-A1FD5046 Our tag: as45393239 [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:14696 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:2081 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7 [Apr 11 14:44:26] DEBUG[21790]: chan_sip.c:2091 __sip_ack: Stopping retransmission on 'e0d141e5-75ab4cb7-1ed315bc@192.168.2.41' of Response 2: Match Not Found [Apr 11 14:44:32] <--- 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=z9hG4bK94fa36f3B8EDAB92 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as45393239 CSeq: 3 BYE Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="58f39b7f", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="c1a971795165f471a5da5eec795382db", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: BYE sip:9XXXXXXXXXX@192.168.2.150 SIP/2.0 (41) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK94fa36f3B8EDAB92 (60) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as45393239 (61) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: CSeq: 3 BYE (11) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: Contact: (32) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/2.1.0.2708 (54) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: Proxy-Authorization: Digest username="2400", realm="asterisk", nonce="58f39b7f", uri="sip:9XXXXXXXXXX@192.168.2.150:5060;user=phone", response="c1a971795165f471a5da5eec795382db", algorithm=MD5 (192) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Max-Forwards: 70 (16) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:44:32] --- (11 headers 0 lines) --- [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4363 find_call: = Found Their Call ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 Their Tag 69BC0C19-A1FD5046 Our tag: as45393239 [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:14696 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 11 14:44:32] Sending to 192.168.2.41 : 5060 (no NAT) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:1635 sip_alreadygone: Setting SIP_ALREADYGONE on dialog e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:14253 handle_request_bye: Received bye, issuing owner hangup [Apr 11 14:44:32] <--- Transmitting (no NAT) to 192.168.2.41:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK94fa36f3B8EDAB92;received=192.168.2.41 From: "2400" ;tag=69BC0C19-A1FD5046 To: ;tag=as45393239 Call-ID: e0d141e5-75ab4cb7-1ed315bc@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:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.41;branch=z9hG4bK94fa36f3B8EDAB92;received=192.168.2.41 (82) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 2: From: "2400" ;tag=69BC0C19-A1FD5046 (59) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 3: To: ;tag=as45393239 (61) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 4: Call-ID: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 (48) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 5: CSeq: 3 BYE (11) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 8: Supported: replaces (19) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 9: Contact: (40) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 10: Content-Length: 0 (17) [Apr 11 14:44:32] DEBUG[21790]: chan_sip.c:4575 parse_request: Header 11: (0) [Apr 11 14:44:32] DEBUG[21806]: channel.c:3828 ast_generic_bridge: Didn't get a frame from channel: SIP/2400-0822af70 [Apr 11 14:44:32] DEBUG[21806]: channel.c:4146 ast_channel_bridge: Bridge stops bridging channels SIP/2400-0822af70 and Zap/1-1 [Apr 11 14:44:32] DEBUG[21806]: channel.c:1698 ast_hangup: Hanging up channel 'Zap/1-1' [Apr 11 14:44:32] DEBUG[21806]: chan_zap.c:2410 zt_hangup: zt_hangup(Zap/1-1) [Apr 11 14:44:32] DEBUG[21806]: chan_zap.c:2443 zt_hangup: Hangup: channel: 1 index = 0, normal = 14, callwait = -1, thirdcall = -1 [Apr 11 14:44:32] DEBUG[21806]: chan_zap.c:1465 zt_disable_ec: disabled echo cancellation on channel 1 [Apr 11 14:44:32] DEBUG[21806]: chan_zap.c:2870 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1 [Apr 11 14:44:32] DEBUG[21806]: chan_zap.c:1402 update_conf: Updated conferencing on 1, with 0 conference users [Apr 11 14:44:32] -- Hungup 'Zap/1-1' [Apr 11 14:44:32] DEBUG[21806]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Apr 11 14:44:32] DEBUG[21806]: rtp.c:1480 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 11 14:44:32] DEBUG[21806]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 11 14:44:32] DEBUG[21806]: pbx.c:2393 __ast_pbx_run: Spawn extension (sip-internal,9XXXXXXXXXX,2) exited non-zero on 'SIP/2400-0822af70' [Apr 11 14:44:32] == Spawn extension (sip-internal, 9XXXXXXXXXX, 2) exited non-zero on 'SIP/2400-0822af70' [Apr 11 14:44:32] DEBUG[21806]: channel.c:1698 ast_hangup: Hanging up channel 'SIP/2400-0822af70' [Apr 11 14:44:32] DEBUG[21806]: chan_sip.c:3314 sip_hangup: Hangup call SIP/2400-0822af70, SIP callid e0d141e5-75ab4cb7-1ed315bc@192.168.2.41) [Apr 11 14:44:32] DEBUG[21806]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-0822af70 [Apr 11 14:44:32] DEBUG[21789]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Apr 11 14:44:32] DEBUG[21789]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown) [Apr 11 14:44:32] DEBUG[21789]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [Apr 11 14:44:32] DEBUG[21789]: chan_sip.c:15307 sip_devicestate: Checking device state for peer 2400 [Apr 11 14:44:32] DEBUG[21789]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [Apr 11 14:44:32] DEBUG[21811]: 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:44:32] DEBUG[21812]: 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:44:33] Really destroying SIP dialog 'e0d141e5-75ab4cb7-1ed315bc@192.168.2.41' Method: BYE [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10732 sip_dump_history: ---------- SIP HISTORY for 'e0d141e5-75ab4cb7-1ed315bc@192.168.2.41' [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10736 sip_dump_history: * SIP Call [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 001. Rx INVITE / 1 INVITE / sip:9XXXXXXXXXX@192.168.2.150:5060;user=pho [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 002. AuthChal Auth challenge sent for - nc 0 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 003. TxRespRel SIP/2.0 / 1 INVITE - 407 Proxy Authentication Required [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 004. SchedDestroy 32000 ms [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 005. Rx ACK / 1 ACK / sip:9XXXXXXXXXX@192.168.2.150:5060 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 006. Rx INVITE / 2 INVITE / sip:9XXXXXXXXXX@192.168.2.150:5060;user=pho [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 007. CancelDestroy [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 008. Invite New call: e0d141e5-75ab4cb7-1ed315bc@192.168.2.41 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 009. AuthOK Auth challenge succesful for 2400 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 010. NewChan Channel SIP/2400-0822af70 - from e0d141e5-75ab4cb7-1ed315bc@192 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 011. TxResp SIP/2.0 / 2 INVITE - 100 Trying [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 012. TxResp SIP/2.0 / 2 INVITE - 183 Session Progress [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 013. TxResp SIP/2.0 / 2 INVITE - 180 Ringing [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 014. TxRespRel SIP/2.0 / 2 INVITE - 200 OK [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 015. Rx ACK / 2 ACK / sip:9XXXXXXXXXX@192.168.2.150 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 016. Rx BYE / 3 BYE / sip:9XXXXXXXXXX@192.168.2.150 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 017. RTCPaudio Quality:ssrc=44822605;themssrc=1919962335;lp=0;rxjitter=0.00007 [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10739 sip_dump_history: 018. TxResp SIP/2.0 / 3 BYE - 200 OK [Apr 11 14:44:33] DEBUG[21790]: chan_sip.c:10742 sip_dump_history: ---------- END SIP HISTORY for 'e0d141e5-75ab4cb7-1ed315bc@192.168.2.41' stop now [Apr 11 14:45:05] Beginning asterisk shutdown.... [Apr 11 14:45:05] Executing last minute cleanups [Apr 11 14:45:05] == Destroying musiconhold processes [Apr 11 14:45:05] Asterisk cleanly ending (0). [Apr 11 14:45:05] DEBUG[21785]: asterisk.c:1276 quit_handler: Asterisk ending (0).