[Feb 21 16:51:27] Asterisk SVN-branch-1.4-r55914, Copyright (C) 1999 - 2006 Digium, Inc. and others. [Feb 21 16:51:27] Created by Mark Spencer [Feb 21 16:51:27] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Feb 21 16:51:27] This is free software, with components licensed under the GNU General Public [Feb 21 16:51:27] License version 2 and other licenses; you are welcome to redistribute it under [Feb 21 16:51:27] certain conditions. Type 'core show license' for details. [Feb 21 16:51:27] ========================================================================= [Feb 21 16:51:28] Asterisk Ready. ]1;Asterisk ]2;Asterisk Console on 'testpbx.novo1nd.com' (pid 2841) *CLI> set debug 4 Core debug was 5 and is now 4 The 'set debug' command is deprecated and will be removed in a future release. Please use 'core set debug' instead. *CLI> core set debug [Feb 21 16:51:43] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for 8095d50e-af04bf80-f278d61d@172.21.10.233 - SUBSCRIBE (No RTP) [Feb 21 16:51:43] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 21 16:51:43] Really destroying SIP dialog '8095d50e-af04bf80-f278d61d@172.21.10.233' Method: SUBSCRIBE 4 Core debug is at least 4 *CLI> core set debug 4verbose 4 Verbosity was 5 and is now 4 *CLI> sip debug SIP Debugging enabled The 'sip debug' command is deprecated and will be removed in a future release. Please use 'sip set debug' instead. *CLI> sip se t debug SIP Debugging re-enabled *CLI> [Feb 21 16:52:36] <--- SIP read from 172.21.10.233:5060 ---> INVITE sip:*@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKe8510c6a28248049 From: "4033" ;tag=D42850-F5DF602D To: CSeq: 1 INVITE Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1172013801 1172013801 IN IP4 172.21.10.233 s=Polycom IP Phone c=IN IP4 172.21.10.233 t=0 0 a=sendrecv m=audio 2258 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: INVITE sip:*@172.21.10.30 SIP/2.0 (33) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKe8510c6a28248049 (61) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=D42850-F5DF602D (56) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (24) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 1 INVITE (14) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 (49) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Supported: 100rel,replaces (26) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: Max-Forwards: 70 (16) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 13: Content-Length: 251 (19) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 14: (0) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: v=0 (3) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: o=- 1172013801 1172013801 IN IP4 172.21.10.233 (46) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: s=Polycom IP Phone (18) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: c=IN IP4 172.21.10.233 (22) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: t=0 0 (5) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=sendrecv (10) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: m=audio 2258 RTP/AVP 0 8 18 101 (31) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 21 16:52:36] --- (14 headers 11 lines) --- [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for 29676c3c-80873d5e-dc73c0b3@172.21.10.233 - INVITE (With RTP) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:1678 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -100rel- [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: 100rel [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -replaces- [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: replaces [Feb 21 16:52:36] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:52:36] Using INVITE request as basis request - 29676c3c-80873d5e-dc73c0b3@172.21.10.233 [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:36] Found user '4033' [Feb 21 16:52:36] Found RTP audio format 0 [Feb 21 16:52:36] Found RTP audio format 8 [Feb 21 16:52:36] Found RTP audio format 18 [Feb 21 16:52:36] Found RTP audio format 101 [Feb 21 16:52:36] Peer audio RTP is at port 172.21.10.233:2258 [Feb 21 16:52:36] Found description format PCMU for ID 0 [Feb 21 16:52:36] Found description format PCMA for ID 8 [Feb 21 16:52:36] Found description format G729 for ID 18 [Feb 21 16:52:36] Found description format telephone-event for ID 101 [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:5115 process_sdp: T38 state changed to 0 on channel [Feb 21 16:52:36] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 21 16:52:36] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 21 16:52:36] Peer audio RTP is at port 172.21.10.233:2258 [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:5195 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:13370 handle_request_invite: Checking SIP call limits for device 4033 [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call [Feb 21 16:52:36] Looking for * in office (domain 172.21.10.30) [Feb 21 16:52:36] <--- Reliably Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 484 Address Incomplete Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKe8510c6a28248049;received=172.21.10.233 From: "4033" ;tag=D42850-F5DF602D To: ;tag=as40bf8b78 Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #63 [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call [Feb 21 16:52:36] Scheduling destruction of SIP dialog '29676c3c-80873d5e-dc73c0b3@172.21.10.233' in 32000 ms (Method: INVITE) [Feb 21 16:52:36] <--- SIP read from 172.21.10.233:5060 ---> ACK sip:*@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKe8510c6a28248049 From: "4033" ;tag=D42850-F5DF602D To: ;tag=as40bf8b78 CSeq: 1 ACK Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: ACK sip:*@172.21.10.30 SIP/2.0 (30) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKe8510c6a28248049 (61) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=D42850-F5DF602D (56) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: ;tag=as40bf8b78 (39) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 1 ACK (11) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 (49) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Max-Forwards: 70 (16) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Content-Length: 0 (17) [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: (0) [Feb 21 16:52:36] --- (11 headers 0 lines) --- [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #63 [Feb 21 16:52:36] DEBUG[2849]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '29676c3c-80873d5e-dc73c0b3@172.21.10.233' of Response 1: Match Not Found [Feb 21 16:52:36] Really destroying SIP dialog '29676c3c-80873d5e-dc73c0b3@172.21.10.233' Method: ACK [Feb 21 16:52:38] <--- SIP read from 172.21.10.233:5060 ---> INVITE sip:*4023@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKcdbe51a488567DFB From: "4033" ;tag=D42850-F5DF602D To: CSeq: 2 INVITE Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1172013802 1172013802 IN IP4 172.21.10.233 s=Polycom IP Phone c=IN IP4 172.21.10.233 t=0 0 a=sendrecv m=audio 2258 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: INVITE sip:*4023@172.21.10.30 SIP/2.0 (37) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKcdbe51a488567DFB (61) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=D42850-F5DF602D (56) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (28) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 2 INVITE (14) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 (49) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Supported: 100rel,replaces (26) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: Max-Forwards: 70 (16) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 13: Content-Length: 251 (19) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 14: (0) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: v=0 (3) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: o=- 1172013802 1172013802 IN IP4 172.21.10.233 (46) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: s=Polycom IP Phone (18) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: c=IN IP4 172.21.10.233 (22) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: t=0 0 (5) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=sendrecv (10) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: m=audio 2258 RTP/AVP 0 8 18 101 (31) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 21 16:52:38] --- (14 headers 11 lines) --- [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for 29676c3c-80873d5e-dc73c0b3@172.21.10.233 - INVITE (With RTP) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:1678 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -100rel- [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: 100rel [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -replaces- [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: replaces [Feb 21 16:52:38] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:52:38] Using INVITE request as basis request - 29676c3c-80873d5e-dc73c0b3@172.21.10.233 [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:38] Found user '4033' [Feb 21 16:52:38] Found RTP audio format 0 [Feb 21 16:52:38] Found RTP audio format 8 [Feb 21 16:52:38] Found RTP audio format 18 [Feb 21 16:52:38] Found RTP audio format 101 [Feb 21 16:52:38] Peer audio RTP is at port 172.21.10.233:2258 [Feb 21 16:52:38] Found description format PCMU for ID 0 [Feb 21 16:52:38] Found description format PCMA for ID 8 [Feb 21 16:52:38] Found description format G729 for ID 18 [Feb 21 16:52:38] Found description format telephone-event for ID 101 [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:5115 process_sdp: T38 state changed to 0 on channel [Feb 21 16:52:38] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 21 16:52:38] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 21 16:52:38] Peer audio RTP is at port 172.21.10.233:2258 [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:5195 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:13370 handle_request_invite: Checking SIP call limits for device 4033 [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call [Feb 21 16:52:38] Looking for *4023 in office (domain 172.21.10.30) [Feb 21 16:52:38] DEBUG[2849]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:3803 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:3804 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:3805 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 21 16:52:38] DEBUG[2849]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:3806 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:3829 sip_new: This channel will not be able to handle video. [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:7956 build_route: build_route: Contact hop: [Feb 21 16:52:38] list_route: hop: [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:13445 handle_request_invite: SIP/4033-09e1bdc8: New call is still down.... Trying... [Feb 21 16:52:38] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKcdbe51a488567DFB;received=172.21.10.233 From: "4033" ;tag=D42850-F5DF602D To: Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 16:52:38] DEBUG[2849]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4033-09e1bdc8 [Feb 21 16:52:38] DEBUG[2846]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4033 [Feb 21 16:52:38] DEBUG[2846]: chan_sip.c:15187 sip_devicestate: Checking device state for peer 4033 [Feb 21 16:52:38] DEBUG[2846]: devicestate.c:287 do_state_change: Changing state for SIP/4033 - state 1 (Not in use) [Feb 21 16:52:38] DEBUG[2875]: pbx.c:1769 pbx_extension_helper: Launching 'Answer' [Feb 21 16:52:38] -- Executing [*4023@office:1] Answer("SIP/4033-09e1bdc8", "") in new stack [Feb 21 16:52:38] DEBUG[2875]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4033-09e1bdc8 [Feb 21 16:52:38] DEBUG[2846]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4033 [Feb 21 16:52:38] DEBUG[2846]: chan_sip.c:15187 sip_devicestate: Checking device state for peer 4033 [Feb 21 16:52:38] DEBUG[2846]: devicestate.c:287 do_state_change: Changing state for SIP/4033 - state 1 (Not in use) [Feb 21 16:52:38] DEBUG[2875]: chan_sip.c:3461 sip_answer: SIP answering channel: SIP/4033-09e1bdc8 [Feb 21 16:52:38] DEBUG[2875]: chan_sip.c:6406 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 21 16:52:38] DEBUG[2875]: chan_sip.c:6174 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Feb 21 16:52:38] DEBUG[2875]: chan_sip.c:6175 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 21 16:52:38] Audio is at 172.21.10.141 port 12474 [Feb 21 16:52:38] Adding codec 0x4 (ulaw) to SDP [Feb 21 16:52:38] Adding codec 0x8 (alaw) to SDP [Feb 21 16:52:38] Adding non-codec 0x1 (telephone-event) to SDP [Feb 21 16:52:38] DEBUG[2875]: chan_sip.c:6306 add_sdp: -- Done with adding codecs to SDP [Feb 21 16:52:38] DEBUG[2875]: chan_sip.c:6351 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 21 16:52:38] <--- Reliably Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bKcdbe51a488567DFB;received=172.21.10.233 From: "4033" ;tag=D42850-F5DF602D To: ;tag=as66d6d86a Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 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: 264 v=0 o=root 2841 2841 IN IP4 172.21.10.141 s=session c=IN IP4 172.21.10.141 t=0 0 m=audio 12474 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 21 16:52:38] DEBUG[2875]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #65 [Feb 21 16:52:38] DEBUG[2875]: pbx.c:1769 pbx_extension_helper: Launching 'Wait' [Feb 21 16:52:38] -- Executing [*4023@office:2] Wait("SIP/4033-09e1bdc8", "2") in new stack [Feb 21 16:52:38] DEBUG[2876]: app_queue.c:546 changethread: Device 'SIP/4033' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 16:52:38] DEBUG[2877]: app_queue.c:546 changethread: Device 'SIP/4033' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 16:52:38] <--- SIP read from 172.21.10.233:5060 ---> ACK sip:*4023@172.21.10.141 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK9b5fa506D84512B5 From: "4033" ;tag=D42850-F5DF602D To: ;tag=as66d6d86a CSeq: 2 ACK Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: ACK sip:*4023@172.21.10.141 SIP/2.0 (35) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK9b5fa506D84512B5 (61) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=D42850-F5DF602D (56) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: ;tag=as66d6d86a (43) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 2 ACK (11) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 (49) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Max-Forwards: 70 (16) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Content-Length: 0 (17) [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: (0) [Feb 21 16:52:38] --- (11 headers 0 lines) --- [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #65 [Feb 21 16:52:38] DEBUG[2849]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '29676c3c-80873d5e-dc73c0b3@172.21.10.233' of Response 2: Match Not Found [Feb 21 16:52:40] DEBUG[2875]: pbx.c:1769 pbx_extension_helper: Launching 'VoiceMail' [Feb 21 16:52:40] -- Executing [*4023@office:3] VoiceMail("SIP/4033-09e1bdc8", "4023|u") in new stack [Feb 21 16:52:40] DEBUG[2875]: app_voicemail.c:2846 leave_voicemail: Before find_user [Feb 21 16:52:40] DEBUG[2875]: app_voicemail.c:2914 leave_voicemail: /var/spool/asterisk/voicemail/default/4023/unavail doesn't exist, doing what we can [Feb 21 16:52:40] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:52:40] DEBUG[2875]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 21 16:52:40] DEBUG[2875]: rtp.c:2687 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 21 16:52:40] -- Playing 'vm-theperson' (language 'en') [Feb 21 16:52:41] <--- SIP read from 172.21.10.233:5060 ---> REGISTER sip:172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK27ab7c38BAEDE6FF From: "4033" ;tag=713340CC-2859CD19 To: CSeq: 5 REGISTER Call-ID: cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233 Contact: ;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER" User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Expires: 3600 Content-Length: 0 <-------------> [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: REGISTER sip:172.21.10.30 SIP/2.0 (33) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK27ab7c38BAEDE6FF (61) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=713340CC-2859CD19 (58) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (27) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 5 REGISTER (16) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233 (49) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: ;methods="INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER" (133) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Expires: 3600 (13) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Content-Length: 0 (17) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: (0) [Feb 21 16:52:41] --- (11 headers 0 lines) --- [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233 - REGISTER (No RTP) [Feb 21 16:52:41] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 21 16:52:41] Using latest REGISTER request as basis request [Feb 21 16:52:41] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:52:41] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK27ab7c38BAEDE6FF;received=172.21.10.233 From: "4033" ;tag=713340CC-2859CD19 To: Call-ID: cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233 CSeq: 5 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 16:52:41] -- Saved useragent "PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043" for peer 4033 [Feb 21 16:52:41] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK27ab7c38BAEDE6FF;received=172.21.10.233 From: "4033" ;tag=713340CC-2859CD19 To: ;tag=as0a206666 Call-ID: cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233 CSeq: 5 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 3600 Contact: ;expires=3600 Date: Wed, 21 Feb 2007 22:52:41 GMT Content-Length: 0 <------------> [Feb 21 16:52:41] DEBUG[2849]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4033 [Feb 21 16:52:41] Scheduling destruction of SIP dialog 'cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233' in 32000 ms (Method: REGISTER) [Feb 21 16:52:41] DEBUG[2846]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4033 [Feb 21 16:52:41] DEBUG[2846]: chan_sip.c:15187 sip_devicestate: Checking device state for peer 4033 [Feb 21 16:52:41] DEBUG[2846]: devicestate.c:287 do_state_change: Changing state for SIP/4033 - state 1 (Not in use) [Feb 21 16:52:41] DEBUG[2878]: app_queue.c:546 changethread: Device 'SIP/4033' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 16:52:42] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:52:42] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:52:42] -- Playing 'digits/4' (language 'en') [Feb 21 16:52:43] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:52:43] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:52:43] -- Playing 'digits/0' (language 'en') [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Feb 21 16:52:44] Scheduling destruction of SIP dialog '301fb40c757f6339627114123ab70165@172.21.10.141' in 32000 ms (Method: NOTIFY) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: NOTIFY sip:4033@172.21.10.233 SIP/2.0 (37) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.141:5060;branch=z9hG4bK792a2a33;rport (64) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "asterisk" ;tag=as08705035 (60) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (28) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: Contact: (37) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 301fb40c757f6339627114123ab70165@172.21.10.141 (55) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Event: message-summary (22) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: Content-Length: 93 (18) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 12: (0) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: Messages-Waiting: no (20) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: Message-Account: sip:asterisk@172.21.10.141 (43) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Feb 21 16:52:44] Reliably Transmitting (no NAT) to 172.21.10.233:5060: NOTIFY sip:4033@172.21.10.233 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.141:5060;branch=z9hG4bK792a2a33;rport From: "asterisk" ;tag=as08705035 To: Contact: Call-ID: 301fb40c757f6339627114123ab70165@172.21.10.141 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@172.21.10.141 Voice-Message: 0/0 (0/0) --- [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #70 [Feb 21 16:52:44] <--- SIP read from 172.21.10.233:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.21.10.141:5060;branch=z9hG4bK792a2a33;rport From: "asterisk" ;tag=as08705035 To: ;tag=A5B61961-413DAE2 CSeq: 102 NOTIFY Call-ID: 301fb40c757f6339627114123ab70165@172.21.10.141 Contact: Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Content-Length: 0 <-------------> [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.141:5060;branch=z9hG4bK792a2a33;rport (64) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "asterisk" ;tag=as08705035 (60) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: ;tag=A5B61961-413DAE2 (49) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 102 NOTIFY (16) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 301fb40c757f6339627114123ab70165@172.21.10.141 (55) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Event: message-summary (22) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Content-Length: 0 (17) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: (0) [Feb 21 16:52:44] --- (10 headers 0 lines) --- [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #70 [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '301fb40c757f6339627114123ab70165@172.21.10.141' of Request 102: Match Not Found [Feb 21 16:52:44] Really destroying SIP dialog '301fb40c757f6339627114123ab70165@172.21.10.141' Method: NOTIFY [Feb 21 16:52:44] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:52:44] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:52:44] -- Playing 'digits/2' (language 'en') [Feb 21 16:52:44] <--- SIP read from 172.21.10.233:5060 ---> SUBSCRIBE sip:1@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK66438b74EF0C3B8B From: "4033" ;tag=A1636F0A-F414ED8F To: CSeq: 1 SUBSCRIBE Call-ID: f05afb56-9f898308-a1f1f2c5@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Accept: application/simple-message-summary Max-Forwards: 70 Expires: 3600 Content-Length: 0 <-------------> [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: SUBSCRIBE sip:1@172.21.10.30 SIP/2.0 (36) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK66438b74EF0C3B8B (61) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=A1636F0A-F414ED8F (58) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (24) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 1 SUBSCRIBE (17) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: f05afb56-9f898308-a1f1f2c5@172.21.10.233 (49) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: Event: message-summary (22) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Accept: application/simple-message-summary (42) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: Max-Forwards: 70 (16) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 12: Expires: 3600 (13) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 13: Content-Length: 0 (17) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 14: (0) [Feb 21 16:52:44] --- (14 headers 0 lines) --- [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for f05afb56-9f898308-a1f1f2c5@172.21.10.233 - SUBSCRIBE (No RTP) [Feb 21 16:52:44] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 21 16:52:44] Creating new subscription [Feb 21 16:52:44] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:52:44] Found peer '4033' [Feb 21 16:52:44] Looking for 1 in office (domain 172.21.10.30) [Feb 21 16:52:44] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK66438b74EF0C3B8B;received=172.21.10.233 From: "4033" ;tag=A1636F0A-F414ED8F To: ;tag=as07e084b5 Call-ID: f05afb56-9f898308-a1f1f2c5@172.21.10.233 CSeq: 1 SUBSCRIBE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Feb 21 16:52:44] Really destroying SIP dialog 'f05afb56-9f898308-a1f1f2c5@172.21.10.233' Method: SUBSCRIBE [Feb 21 16:52:45] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:52:45] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:52:45] -- Playing 'digits/3' (language 'en') [Feb 21 16:52:45] DEBUG[2875]: rtp.c:871 ast_rtcp_read: Got RTCP report of 80 bytes [Feb 21 16:52:45] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:52:45] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:52:45] -- Playing 'vm-isunavail' (language 'en') [Feb 21 16:52:47] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:52:47] DEBUG[2875]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:52:47] -- Playing 'vm-intro' (language 'en') [Feb 21 16:52:50] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:50] DEBUG[2875]: rtp.c:626 send_dtmf: Sending dtmf: 42 (*), at 172.21.10.233 [Feb 21 16:52:50] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:50] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:50] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:50] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:50] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:50] DEBUG[2875]: rtp.c:626 send_dtmf: Sending dtmf: 42 (*), at 172.21.10.233 [Feb 21 16:52:51] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:51] DEBUG[2875]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000a (len = 4) [Feb 21 16:52:52] <--- SIP read from 172.21.10.233:5060 ---> BYE sip:*4023@172.21.10.141 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK297d604d601F75F0 From: "4033" ;tag=D42850-F5DF602D To: ;tag=as66d6d86a CSeq: 3 BYE Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: BYE sip:*4023@172.21.10.141 SIP/2.0 (35) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK297d604d601F75F0 (61) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=D42850-F5DF602D (56) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: ;tag=as66d6d86a (43) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 3 BYE (11) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 (49) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Content-Length: 0 (17) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: (0) [Feb 21 16:52:52] --- (10 headers 0 lines) --- [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 21 16:52:52] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:1631 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 29676c3c-80873d5e-dc73c0b3@172.21.10.233 [Feb 21 16:52:52] DEBUG[2849]: chan_sip.c:14159 handle_request_bye: Received bye, issuing owner hangup [Feb 21 16:52:52] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK297d604d601F75F0;received=172.21.10.233 From: "4033" ;tag=D42850-F5DF602D To: ;tag=as66d6d86a Call-ID: 29676c3c-80873d5e-dc73c0b3@172.21.10.233 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 16:52:52] DEBUG[2875]: pbx.c:2367 __ast_pbx_run: Spawn extension (office,*4023,3) exited non-zero on 'SIP/4033-09e1bdc8' [Feb 21 16:52:52] == Spawn extension (office, *4023, 3) exited non-zero on 'SIP/4033-09e1bdc8' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"Test Phone" <4033>' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4033' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '*4023' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'office' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/4033-09e1bdc8' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'VoiceMail' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4023|u' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-21 16:52:38' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-21 16:52:38' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-21 16:52:52' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '14' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '14' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1172098358.0' [Feb 21 16:52:52] DEBUG[2875]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 16:52:52] DEBUG[2875]: cdr_addon_mysql.c:211 mysql_log: cdr_mysql: inserting a CDR record. [Feb 21 16:52:52] DEBUG[2875]: cdr_addon_mysql.c:227 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdrwilliston (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-02-21 16:52:38','\"Test Phone\" <4033>','4033','*4023','office', 'SIP/4033-09e1bdc8','','VoiceMail','4023|u',14,14,'ANSWERED',3,'','1172098358.0','') [Feb 21 16:52:52] DEBUG[2875]: channel.c:1689 ast_hangup: Hanging up channel 'SIP/4033-09e1bdc8' [Feb 21 16:52:52] DEBUG[2875]: chan_sip.c:3310 sip_hangup: Hangup call SIP/4033-09e1bdc8, SIP callid 29676c3c-80873d5e-dc73c0b3@172.21.10.233) [Feb 21 16:52:52] DEBUG[2875]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4033-09e1bdc8 [Feb 21 16:52:52] DEBUG[2846]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4033 [Feb 21 16:52:52] DEBUG[2846]: chan_sip.c:15187 sip_devicestate: Checking device state for peer 4033 [Feb 21 16:52:52] DEBUG[2846]: devicestate.c:287 do_state_change: Changing state for SIP/4033 - state 1 (Not in use) [Feb 21 16:52:52] DEBUG[2880]: app_queue.c:546 changethread: Device 'SIP/4033' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 16:52:53] Really destroying SIP dialog '29676c3c-80873d5e-dc73c0b3@172.21.10.233' Method: BYE [Feb 21 16:52:57] <--- SIP read from 172.21.10.233:5060 ---> INVITE sip:*@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK73eb81f95EA4E5A From: "4033" ;tag=21D6D65D-2D47AE4E To: CSeq: 1 INVITE Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1172013822 1172013822 IN IP4 172.21.10.233 s=Polycom IP Phone c=IN IP4 172.21.10.233 t=0 0 a=sendrecv m=audio 2260 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: INVITE sip:*@172.21.10.30 SIP/2.0 (33) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK73eb81f95EA4E5A (60) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=21D6D65D-2D47AE4E (58) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (24) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 1 INVITE (14) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 (49) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Supported: 100rel,replaces (26) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: Max-Forwards: 70 (16) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 13: Content-Length: 251 (19) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 14: (0) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: v=0 (3) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: o=- 1172013822 1172013822 IN IP4 172.21.10.233 (46) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: s=Polycom IP Phone (18) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: c=IN IP4 172.21.10.233 (22) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: t=0 0 (5) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=sendrecv (10) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: m=audio 2260 RTP/AVP 0 8 18 101 (31) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 21 16:52:57] --- (14 headers 11 lines) --- [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for 8ab6f379-b0b85f63-b62857ac@172.21.10.233 - INVITE (With RTP) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:1678 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -100rel- [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: 100rel [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -replaces- [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: replaces [Feb 21 16:52:57] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:52:57] Using INVITE request as basis request - 8ab6f379-b0b85f63-b62857ac@172.21.10.233 [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:57] Found user '4033' [Feb 21 16:52:57] Found RTP audio format 0 [Feb 21 16:52:57] Found RTP audio format 8 [Feb 21 16:52:57] Found RTP audio format 18 [Feb 21 16:52:57] Found RTP audio format 101 [Feb 21 16:52:57] Peer audio RTP is at port 172.21.10.233:2260 [Feb 21 16:52:57] Found description format PCMU for ID 0 [Feb 21 16:52:57] Found description format PCMA for ID 8 [Feb 21 16:52:57] Found description format G729 for ID 18 [Feb 21 16:52:57] Found description format telephone-event for ID 101 [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:5115 process_sdp: T38 state changed to 0 on channel [Feb 21 16:52:57] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 21 16:52:57] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 21 16:52:57] Peer audio RTP is at port 172.21.10.233:2260 [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:5195 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:13370 handle_request_invite: Checking SIP call limits for device 4033 [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call [Feb 21 16:52:57] Looking for * in office (domain 172.21.10.30) [Feb 21 16:52:57] <--- Reliably Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 484 Address Incomplete Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK73eb81f95EA4E5A;received=172.21.10.233 From: "4033" ;tag=21D6D65D-2D47AE4E To: ;tag=as5d4f537b Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #71 [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call [Feb 21 16:52:57] Scheduling destruction of SIP dialog '8ab6f379-b0b85f63-b62857ac@172.21.10.233' in 32000 ms (Method: INVITE) [Feb 21 16:52:57] <--- SIP read from 172.21.10.233:5060 ---> ACK sip:*@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK73eb81f95EA4E5A From: "4033" ;tag=21D6D65D-2D47AE4E To: ;tag=as5d4f537b CSeq: 1 ACK Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: ACK sip:*@172.21.10.30 SIP/2.0 (30) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK73eb81f95EA4E5A (60) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=21D6D65D-2D47AE4E (58) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: ;tag=as5d4f537b (39) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 1 ACK (11) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 (49) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Max-Forwards: 70 (16) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Content-Length: 0 (17) [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: (0) [Feb 21 16:52:57] --- (11 headers 0 lines) --- [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #71 [Feb 21 16:52:57] DEBUG[2849]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '8ab6f379-b0b85f63-b62857ac@172.21.10.233' of Response 1: Match Not Found [Feb 21 16:52:57] Really destroying SIP dialog '8ab6f379-b0b85f63-b62857ac@172.21.10.233' Method: ACK [Feb 21 16:52:59] <--- SIP read from 172.21.10.233:5060 ---> INVITE sip:*4023@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK2daec381600D3B14 From: "4033" ;tag=21D6D65D-2D47AE4E To: CSeq: 2 INVITE Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 251 v=0 o=- 1172013823 1172013823 IN IP4 172.21.10.233 s=Polycom IP Phone c=IN IP4 172.21.10.233 t=0 0 a=sendrecv m=audio 2260 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 <-------------> [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: INVITE sip:*4023@172.21.10.30 SIP/2.0 (37) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK2daec381600D3B14 (61) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=21D6D65D-2D47AE4E (58) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (28) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 2 INVITE (14) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 (49) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Supported: 100rel,replaces (26) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Allow-Events: talk,hold,conference (34) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: Max-Forwards: 70 (16) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 13: Content-Length: 251 (19) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 14: (0) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: v=0 (3) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: o=- 1172013823 1172013823 IN IP4 172.21.10.233 (46) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: s=Polycom IP Phone (18) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: c=IN IP4 172.21.10.233 (22) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: t=0 0 (5) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=sendrecv (10) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: m=audio 2260 RTP/AVP 0 8 18 101 (31) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4595 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 21 16:52:59] --- (14 headers 11 lines) --- [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for 8ab6f379-b0b85f63-b62857ac@172.21.10.233 - INVITE (With RTP) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:1678 parse_sip_options: Begin: parsing SIP "Supported: 100rel,replaces" [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -100rel- [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: 100rel [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:1686 parse_sip_options: Found SIP option: -replaces- [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:1692 parse_sip_options: Matched SIP option: replaces [Feb 21 16:52:59] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:52:59] Using INVITE request as basis request - 8ab6f379-b0b85f63-b62857ac@172.21.10.233 [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:2573 do_setnat: Setting NAT on RTP to Off [Feb 21 16:52:59] Found user '4033' [Feb 21 16:52:59] Found RTP audio format 0 [Feb 21 16:52:59] Found RTP audio format 8 [Feb 21 16:52:59] Found RTP audio format 18 [Feb 21 16:52:59] Found RTP audio format 101 [Feb 21 16:52:59] Peer audio RTP is at port 172.21.10.233:2260 [Feb 21 16:52:59] Found description format PCMU for ID 0 [Feb 21 16:52:59] Found description format PCMA for ID 8 [Feb 21 16:52:59] Found description format G729 for ID 18 [Feb 21 16:52:59] Found description format telephone-event for ID 101 [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:5115 process_sdp: T38 state changed to 0 on channel [Feb 21 16:52:59] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Feb 21 16:52:59] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 21 16:52:59] Peer audio RTP is at port 172.21.10.233:2260 [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:5195 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:13370 handle_request_invite: Checking SIP call limits for device 4033 [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:3001 update_call_counter: Updating call counter for incoming call [Feb 21 16:52:59] Looking for *4023 in office (domain 172.21.10.30) [Feb 21 16:52:59] DEBUG[2849]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:3803 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:3804 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:3805 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 21 16:52:59] DEBUG[2849]: frame.c:1267 ast_codec_choose: Could not find preferred codec - Going for the best codec [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:3806 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:3829 sip_new: This channel will not be able to handle video. [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:7956 build_route: build_route: Contact hop: [Feb 21 16:52:59] list_route: hop: [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:13445 handle_request_invite: SIP/4033-09e1bdc8: New call is still down.... Trying... [Feb 21 16:52:59] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK2daec381600D3B14;received=172.21.10.233 From: "4033" ;tag=21D6D65D-2D47AE4E To: Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 16:52:59] DEBUG[2849]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4033-09e1bdc8 [Feb 21 16:52:59] DEBUG[2846]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4033 [Feb 21 16:52:59] DEBUG[2846]: chan_sip.c:15187 sip_devicestate: Checking device state for peer 4033 [Feb 21 16:52:59] DEBUG[2846]: devicestate.c:287 do_state_change: Changing state for SIP/4033 - state 1 (Not in use) [Feb 21 16:52:59] DEBUG[2881]: pbx.c:1769 pbx_extension_helper: Launching 'Answer' [Feb 21 16:52:59] -- Executing [*4023@office:1] Answer("SIP/4033-09e1bdc8", "") in new stack [Feb 21 16:52:59] DEBUG[2881]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4033-09e1bdc8 [Feb 21 16:52:59] DEBUG[2846]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4033 [Feb 21 16:52:59] DEBUG[2846]: chan_sip.c:15187 sip_devicestate: Checking device state for peer 4033 [Feb 21 16:52:59] DEBUG[2846]: devicestate.c:287 do_state_change: Changing state for SIP/4033 - state 1 (Not in use) [Feb 21 16:52:59] DEBUG[2881]: chan_sip.c:3461 sip_answer: SIP answering channel: SIP/4033-09e1bdc8 [Feb 21 16:52:59] DEBUG[2881]: chan_sip.c:6406 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 21 16:52:59] DEBUG[2881]: chan_sip.c:6174 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Feb 21 16:52:59] DEBUG[2881]: chan_sip.c:6175 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 21 16:52:59] Audio is at 172.21.10.141 port 18076 [Feb 21 16:52:59] Adding codec 0x4 (ulaw) to SDP [Feb 21 16:52:59] DEBUG[2882]: app_queue.c:546 changethread: Device 'SIP/4033' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 16:52:59] DEBUG[2883]: app_queue.c:546 changethread: Device 'SIP/4033' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 16:52:59] Adding codec 0x8 (alaw) to SDP [Feb 21 16:52:59] Adding non-codec 0x1 (telephone-event) to SDP [Feb 21 16:52:59] DEBUG[2881]: chan_sip.c:6306 add_sdp: -- Done with adding codecs to SDP [Feb 21 16:52:59] DEBUG[2881]: chan_sip.c:6351 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Feb 21 16:52:59] <--- Reliably Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK2daec381600D3B14;received=172.21.10.233 From: "4033" ;tag=21D6D65D-2D47AE4E To: ;tag=as0649f5d6 Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 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: 264 v=0 o=root 2841 2841 IN IP4 172.21.10.141 s=session c=IN IP4 172.21.10.141 t=0 0 m=audio 18076 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 21 16:52:59] DEBUG[2881]: chan_sip.c:1973 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #73 [Feb 21 16:52:59] DEBUG[2881]: pbx.c:1769 pbx_extension_helper: Launching 'Wait' [Feb 21 16:52:59] -- Executing [*4023@office:2] Wait("SIP/4033-09e1bdc8", "2") in new stack [Feb 21 16:52:59] <--- SIP read from 172.21.10.233:5060 ---> ACK sip:*4023@172.21.10.141 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK75bc42ab1B7943F6 From: "4033" ;tag=21D6D65D-2D47AE4E To: ;tag=as0649f5d6 CSeq: 2 ACK Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: ACK sip:*4023@172.21.10.141 SIP/2.0 (35) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK75bc42ab1B7943F6 (61) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=21D6D65D-2D47AE4E (58) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: ;tag=as0649f5d6 (43) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 2 ACK (11) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 (49) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Max-Forwards: 70 (16) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Content-Length: 0 (17) [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: (0) [Feb 21 16:52:59] --- (11 headers 0 lines) --- [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:2077 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #73 [Feb 21 16:52:59] DEBUG[2849]: chan_sip.c:2087 __sip_ack: Stopping retransmission on '8ab6f379-b0b85f63-b62857ac@172.21.10.233' of Response 2: Match Not Found [Feb 21 16:53:01] DEBUG[2881]: pbx.c:1769 pbx_extension_helper: Launching 'VoiceMail' [Feb 21 16:53:01] -- Executing [*4023@office:3] VoiceMail("SIP/4033-09e1bdc8", "4023|u") in new stack [Feb 21 16:53:01] DEBUG[2881]: app_voicemail.c:2846 leave_voicemail: Before find_user [Feb 21 16:53:01] DEBUG[2881]: app_voicemail.c:2914 leave_voicemail: /var/spool/asterisk/voicemail/default/4023/unavail doesn't exist, doing what we can [Feb 21 16:53:01] DEBUG[2881]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:53:01] DEBUG[2881]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 21 16:53:01] DEBUG[2881]: rtp.c:2687 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Feb 21 16:53:01] -- Playing 'vm-theperson' (language 'en') [Feb 21 16:53:03] DEBUG[2881]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:53:03] DEBUG[2881]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:53:03] -- Playing 'digits/4' (language 'en') [Feb 21 16:53:03] DEBUG[2881]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:53:03] DEBUG[2881]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format gsm [Feb 21 16:53:03] -- Playing 'digits/0' (language 'en') [Feb 21 16:53:04] <--- SIP read from 172.21.10.233:5060 ---> BYE sip:*4023@172.21.10.141 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK89a86e9153EBB0E4 From: "4033" ;tag=21D6D65D-2D47AE4E To: ;tag=as0649f5d6 CSeq: 3 BYE Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 Contact: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: BYE sip:*4023@172.21.10.141 SIP/2.0 (35) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK89a86e9153EBB0E4 (61) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=21D6D65D-2D47AE4E (58) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: ;tag=as0649f5d6 (43) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 3 BYE (11) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 (49) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: Content-Length: 0 (17) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: (0) [Feb 21 16:53:04] --- (10 headers 0 lines) --- [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 21 16:53:04] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:1631 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 8ab6f379-b0b85f63-b62857ac@172.21.10.233 [Feb 21 16:53:04] DEBUG[2849]: chan_sip.c:14159 handle_request_bye: Received bye, issuing owner hangup [Feb 21 16:53:04] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK89a86e9153EBB0E4;received=172.21.10.233 From: "4033" ;tag=21D6D65D-2D47AE4E To: ;tag=as0649f5d6 Call-ID: 8ab6f379-b0b85f63-b62857ac@172.21.10.233 CSeq: 3 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 21 16:53:04] DEBUG[2881]: channel.c:2841 set_format: Set channel SIP/4033-09e1bdc8 to write format ulaw [Feb 21 16:53:04] DEBUG[2881]: app_voicemail.c:2920 leave_voicemail: Hang up during prefile playback [Feb 21 16:53:04] DEBUG[2881]: pbx.c:2367 __ast_pbx_run: Spawn extension (office,*4023,3) exited non-zero on 'SIP/4033-09e1bdc8' [Feb 21 16:53:04] == Spawn extension (office, *4023, 3) exited non-zero on 'SIP/4033-09e1bdc8' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"Test Phone" <4033>' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4033' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '*4023' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'office' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/4033-09e1bdc8' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'VoiceMail' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4023|u' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-21 16:52:59' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-21 16:52:59' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-21 16:53:04' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '5' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1172098379.1' [Feb 21 16:53:04] DEBUG[2881]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 21 16:53:04] DEBUG[2881]: cdr_addon_mysql.c:211 mysql_log: cdr_mysql: inserting a CDR record. [Feb 21 16:53:04] DEBUG[2881]: cdr_addon_mysql.c:227 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdrwilliston (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-02-21 16:52:59','\"Test Phone\" <4033>','4033','*4023','office', 'SIP/4033-09e1bdc8','','VoiceMail','4023|u',5,5,'ANSWERED',3,'','1172098379.1','') [Feb 21 16:53:04] DEBUG[2881]: channel.c:1689 ast_hangup: Hanging up channel 'SIP/4033-09e1bdc8' [Feb 21 16:53:04] DEBUG[2881]: chan_sip.c:3310 sip_hangup: Hangup call SIP/4033-09e1bdc8, SIP callid 8ab6f379-b0b85f63-b62857ac@172.21.10.233) [Feb 21 16:53:04] DEBUG[2881]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4033-09e1bdc8 [Feb 21 16:53:04] DEBUG[2846]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4033 [Feb 21 16:53:04] DEBUG[2846]: chan_sip.c:15187 sip_devicestate: Checking device state for peer 4033 [Feb 21 16:53:04] DEBUG[2846]: devicestate.c:287 do_state_change: Changing state for SIP/4033 - state 1 (Not in use) [Feb 21 16:53:04] DEBUG[2885]: app_queue.c:546 changethread: Device 'SIP/4033' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 21 16:53:05] Really destroying SIP dialog '8ab6f379-b0b85f63-b62857ac@172.21.10.233' Method: BYE [Feb 21 16:53:13] DEBUG[2849]: chan_sip.c:2008 __sip_autodestruct: Auto destroying SIP dialog 'cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233' [Feb 21 16:53:13] DEBUG[2849]: chan_sip.c:3107 sip_destroy: Destroying SIP dialog cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233 [Feb 21 16:53:13] Really destroying SIP dialog 'cd0d74f8-4fc68a7a-ce7450bf@172.21.10.233' Method: REGISTER *CLI> exit No such command 'exit' (type 'help' for help) *CLI> cd /temp No such command 'cd /temp' (type 'help' for help) *CLI> ls No such command 'ls' (type 'help' for help) *CLI> ls No such command 'ls' (type 'help' for help) *CLI> exit No such command 'exit' (type 'help' for help) *CLI> [Feb 21 16:53:45] <--- SIP read from 172.21.10.233:5060 ---> SUBSCRIBE sip:1@172.21.10.30 SIP/2.0 Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK8cda89991EF0834C From: "4033" ;tag=2BA6DC07-4C32A060 To: CSeq: 1 SUBSCRIBE Call-ID: 1a1b3283-66d3ae7d-93fed2ee@172.21.10.233 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER Event: message-summary User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 Accept: application/simple-message-summary Max-Forwards: 70 Expires: 3600 Content-Length: 0 <-------------> [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 0: SUBSCRIBE sip:1@172.21.10.30 SIP/2.0 (36) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 1: Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK8cda89991EF0834C (61) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 2: From: "4033" ;tag=2BA6DC07-4C32A060 (58) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 3: To: (24) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 4: CSeq: 1 SUBSCRIBE (17) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 5: Call-ID: 1a1b3283-66d3ae7d-93fed2ee@172.21.10.233 (49) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 6: Contact: (33) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER (96) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 8: Event: message-summary (22) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 9: User-Agent: PolycomSoundPointIP-SPIP_501-UA/1.6.5.0043 (54) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 10: Accept: application/simple-message-summary (42) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 11: Max-Forwards: 70 (16) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 12: Expires: 3600 (13) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 13: Content-Length: 0 (17) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4563 parse_request: Header 14: (0) [Feb 21 16:53:45] --- (14 headers 0 lines) --- [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:4300 sip_alloc: Allocating new SIP dialog for 1a1b3283-66d3ae7d-93fed2ee@172.21.10.233 - SUBSCRIBE (No RTP) [Feb 21 16:53:45] DEBUG[2849]: chan_sip.c:14582 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 21 16:53:45] Creating new subscription [Feb 21 16:53:45] Sending to 172.21.10.233 : 5060 (no NAT) [Feb 21 16:53:45] Found peer '4033' [Feb 21 16:53:45] Looking for 1 in office (domain 172.21.10.30) [Feb 21 16:53:45] <--- Transmitting (no NAT) to 172.21.10.233:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 172.21.10.233;branch=z9hG4bK8cda89991EF0834C;received=172.21.10.233 From: "4033" ;tag=2BA6DC07-4C32A060 To: ;tag=as188d5889 Call-ID: 1a1b3283-66d3ae7d-93fed2ee@172.21.10.233 CSeq: 1 SUBSCRIBE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Feb 21 16:53:45] Really destroying SIP dialog '1a1b3283-66d3ae7d-93fed2ee@172.21.10.233' Method: SUBSCRIBE *CLI> tsstop now [Feb 21 16:53:51] Beginning asterisk shutdown.... [Feb 21 16:53:51] Executing last minute cleanups [Feb 21 16:53:51] == Destroying musiconhold processes [Feb 21 16:53:51] Asterisk cleanly ending (0). [Feb 21 16:53:51] DEBUG[2841]: asterisk.c:1192 quit_handler: Asterisk ending (0).