[Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 48]: INVITE sip:86@butthead.lan;transport=UDP SIP/2.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 25]: To: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 14]: CSeq: 1 INVITE [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c22399-7e5b1133-522d776c [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 9]: Min-SE: 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 19]: Content-Length: 333 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 3]: v=0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 1 [ 37]: o=a0000 8645 6672 IN IP4 192.168.5.33 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 10]: s=SIP Call [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 3 [ 21]: c=IN IP4 192.168.5.33 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 4 [ 5]: t=0 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 5 [ 41]: m=audio 10052 RTP/AVP 8 0 2 21 23 22 18 4 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 9 [ 24]: a=rtpmap:21 G726-40/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 10 [ 24]: a=rtpmap:23 G726-16/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 11 [ 24]: a=rtpmap:22 G726-24/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 12 [ 21]: a=rtpmap:18 G729/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 13 [ 20]: a=rtpmap:4 G723/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 14 [ 10]: a=sendrecv [Feb 1 20:30:01] DEBUG[20818]: acl.c:215 ast_apply_ha: ##### Testing 192.168.5.33 with 192.168.5.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2703 do_setnat: Setting NAT on RTP to Off [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2713 do_setnat: Setting NAT on UDPTL to Off [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4404 sip_alloc: Allocating new SIP dialog for 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan - INVITE (With RTP) [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:1739 parse_sip_options: Begin: parsing SIP "Supported: replaces,timer,100rel" [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:1747 parse_sip_options: Found SIP option: -replaces- [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:1753 parse_sip_options: Matched SIP option: replaces [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:1747 parse_sip_options: Found SIP option: -timer- [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:1753 parse_sip_options: Matched SIP option: timer [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:1747 parse_sip_options: Found SIP option: -100rel- [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:1753 parse_sip_options: Matched SIP option: 100rel [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:13462 handle_request_invite: Initializing initreq for method INVITE - callid 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2703 do_setnat: Setting NAT on RTP to Off [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2713 do_setnat: Setting NAT on UDPTL to Off [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 24]: SIP/2.0 401 Unauthorized [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c22399-7e5b1133-522d776c;received=192.168.5.33;rport=10000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as3fd4f72a [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 14]: CSeq: 1 INVITE [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 74]: WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2d8ccbc6" [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2029 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7495 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 45]: ACK sip:86@butthead.lan;transport=UDP SIP/2.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as3fd4f72a [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c22399-7e5b1133-522d776c [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 50]: Contact: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 17]: Content-Length: 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 0]: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7495 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2139 __sip_ack: Stopping retransmission on '10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan' of Response 1: Match Found butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 48]: INVITE sip:86@butthead.lan;transport=UDP SIP/2.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 25]: To: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 14]: CSeq: 2 INVITE [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c22399-7e5b1151-21949000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [167]: Authorization: Digest username="12",realm="asterisk",nonce="2d8ccbc6",uri="sip:86@butthead.lan;transport=UDP",response="39cb2ed1d2e1182654a86c7a6a045875",algorithm=MD5 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 9]: Min-SE: 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 19]: Content-Length: 333 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 14 [ 0]: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 3]: v=0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 1 [ 37]: o=a0000 8645 6672 IN IP4 192.168.5.33 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 10]: s=SIP Call [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 3 [ 21]: c=IN IP4 192.168.5.33 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 4 [ 5]: t=0 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 5 [ 41]: m=audio 10052 RTP/AVP 8 0 2 21 23 22 18 4 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 9 [ 24]: a=rtpmap:21 G726-40/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 10 [ 24]: a=rtpmap:23 G726-16/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 11 [ 24]: a=rtpmap:22 G726-24/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 12 [ 21]: a=rtpmap:18 G729/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 13 [ 20]: a=rtpmap:4 G723/8000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 14 [ 10]: a=sendrecv [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:13462 handle_request_invite: Initializing initreq for method INVITE - callid 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2703 do_setnat: Setting NAT on RTP to Off [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2713 do_setnat: Setting NAT on UDPTL to Off [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:5201 process_sdp: T38 state changed to 0 on channel [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:5278 process_sdp: We're settling with these formats: 0x10c (ulaw|alaw|g729) [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:13543 handle_request_invite: Checking SIP call limits for device 12 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:3128 update_call_counter: Updating call counter for incoming call [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:3907 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:3908 sip_new: *** Joint capabilities are 0x10c (ulaw|alaw|g729) butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:3909 sip_new: *** Our capabilities are 0x10c (ulaw|alaw|g729) [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:3910 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:3933 sip_new: This channel will not be able to handle video. [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:8012 build_route: build_route: Contact hop: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:13618 handle_request_invite: SIP/12-081bcf00: New call is still down.... Trying... [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c22399-7e5b1151-21949000;received=192.168.5.33;rport=10000 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 25]: To: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 14]: CSeq: 2 INVITE [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 30]: Contact: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/12-081bcf00 [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:371 do_state_change: Changing state for SIP/12 - state 1 (Not in use) [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: pbx.c:1693 pbx_extension_helper: Launching 'VoiceMailMain' butthead*CLI> -- Executing [86@longdistance:1] VoiceMailMain("SIP/12-081bcf00", "") in new stack butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: app_voicemail.c:6234 vm_execmain: Before ast_answer butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/12-081bcf00 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:371 do_state_change: Changing state for SIP/12 - state 1 (Not in use) [Feb 1 20:30:01] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:3569 sip_answer: SIP answering channel: SIP/12-081bcf00 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:6506 transmit_response_with_sdp: Setting framing from config on incoming call butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:6281 add_sdp: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: True butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:6282 add_sdp: ** Our prefcodec: 0x0 (nothing) butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:6407 add_sdp: -- Done with adding codecs to SDP butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:6451 add_sdp: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729) butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 14]: SIP/2.0 200 OK butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c22399-7e5b1151-21949000;received=192.168.5.33;rport=10000 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as01d1be2e butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 14]: CSeq: 2 INVITE butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 30]: Contact: butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 29]: Content-Type: application/sdp butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 19]: Content-Length: 255 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 0]: butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 3]: v=0 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 1 [ 38]: o=root 20815 20815 IN IP4 192.168.5.77 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 9]: s=session butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 3 [ 21]: c=IN IP4 192.168.5.77 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 4 [ 5]: t=0 0 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 5 [ 28]: m=audio 15068 RTP/AVP 0 8 18 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 8 [ 21]: a=rtpmap:18 G729/8000 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 9 [ 19]: a=fmtp:18 annexb=no butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 10 [ 25]: a=silenceSupp:off - - - - butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 11 [ 10]: a=ptime:20 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 12 [ 10]: a=sendrecv butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2029 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7497 butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: app_queue.c:568 changethread: Device 'SIP/12' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: app_queue.c:568 changethread: Device 'SIP/12' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. butthead*CLI> [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 31]: ACK sip:86@192.168.5.77 SIP/2.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c22399-7e5b116f-11048f52 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 50]: Contact: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [167]: Authorization: Digest username="12",realm="asterisk",nonce="2d8ccbc6",uri="sip:86@butthead.lan;transport=UDP",response="39cb2ed1d2e1182654a86c7a6a045875",algorithm=MD5 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7497 [Feb 1 20:30:01] DEBUG[20818]: chan_sip.c:2139 __sip_ack: Stopping retransmission on '10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan' of Response 2: Match Found butthead*CLI> [Feb 1 20:30:02] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format alaw [Feb 1 20:30:02] DEBUG[20818]: rtp.c:2757 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 1 20:30:02] DEBUG[20818]: rtp.c:2774 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 -- Playing 'vm-login' (language 'en') butthead*CLI> [Feb 1 20:30:04] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format ulaw butthead*CLI> [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 32]: INFO sip:86@192.168.5.77 SIP/2.0 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 12]: CSeq: 3 INFO [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c2239d-7e5b20ab-30835d9e [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [153]: Authorization: Digest username="12",realm="asterisk",nonce="2d8ccbc6",uri="sip:86@192.168.5.77",response="2e3c5d1f75b9a0a1f25f2831649c93e0",algorithm=MD5 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 30]: Content-Type: application/text [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 18]: Content-Length: 21 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received INFO (13) - Command in SIP INFO [Feb 1 20:30:05] WARNING[20818]: chan_sip.c:11002 handle_request_info: Unable to parse INFO message from 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan. Content +oć¬ [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 34]: SIP/2.0 415 Unsupported media type [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c2239d-7e5b20ab-30835d9e;received=192.168.5.33;rport=10000 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 12]: CSeq: 3 INFO [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 17]: Content-Length: 0 [Feb 1 20:30:05] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 0]: butthead*CLI> [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 32]: INFO sip:86@192.168.5.77 SIP/2.0 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 12]: CSeq: 4 INFO [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 82]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c2239f-7e5b25a1-f882aff [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [153]: Authorization: Digest username="12",realm="asterisk",nonce="2d8ccbc6",uri="sip:86@192.168.5.77",response="2e3c5d1f75b9a0a1f25f2831649c93e0",algorithm=MD5 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 30]: Content-Type: application/text [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 18]: Content-Length: 21 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received INFO (13) - Command in SIP INFO [Feb 1 20:30:07] WARNING[20818]: chan_sip.c:11002 handle_request_info: Unable to parse INFO message from 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan. Content +oć¬ [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 34]: SIP/2.0 415 Unsupported media type [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [110]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c2239f-7e5b25a1-f882aff;received=192.168.5.33;rport=10000 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 12]: CSeq: 4 INFO [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 17]: Content-Length: 0 [Feb 1 20:30:07] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 0]: butthead*CLI> [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 32]: INFO sip:86@192.168.5.77 SIP/2.0 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 12]: CSeq: 5 INFO [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c223a1-7e5b2f3d-4d5c7aef [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [153]: Authorization: Digest username="12",realm="asterisk",nonce="2d8ccbc6",uri="sip:86@192.168.5.77",response="2e3c5d1f75b9a0a1f25f2831649c93e0",algorithm=MD5 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 30]: Content-Type: application/text [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 18]: Content-Length: 21 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received INFO (13) - Command in SIP INFO [Feb 1 20:30:09] WARNING[20818]: chan_sip.c:11002 handle_request_info: Unable to parse INFO message from 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan. Content +oć¬ [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 34]: SIP/2.0 415 Unsupported media type [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c223a1-7e5b2f3d-4d5c7aef;received=192.168.5.33;rport=10000 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 12]: CSeq: 5 INFO [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 17]: Content-Length: 0 [Feb 1 20:30:09] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 0]: butthead*CLI> [Feb 1 20:30:15] DEBUG[20818]: app_voicemail.c:6141 vm_authenticate: Before find user for mailbox 12 [Feb 1 20:30:15] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format alaw [Feb 1 20:30:15] DEBUG[20818]: rtp.c:2626 ast_rtp_raw_write: Difference is 83936, ms is 10512 -- Playing 'vm-password' (language 'en') butthead*CLI> [Feb 1 20:30:16] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format ulaw butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 31]: BYE sip:86@192.168.5.77 SIP/2.0 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 11]: CSeq: 6 BYE [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c223aa-7e5b52e7-371e6144 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [153]: Authorization: Digest username="12",realm="asterisk",nonce="2d8ccbc6",uri="sip:86@192.168.5.77",response="7ac4836fe5dc8817b944833df4b157ac",algorithm=MD5 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:14284 handle_request_bye: Initializing initreq for method BYE - callid 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:1692 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:14334 handle_request_bye: Received bye, issuing owner hangup [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c223aa-7e5b52e7-371e6144;received=192.168.5.33;rport=10000 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10194b18-2105a8c0-2710-45c22399-4a920042-45c22399 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as01d1be2e [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 11]: CSeq: 6 BYE [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 30]: Contact: [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: butthead*CLI> [Feb 1 20:30:18] WARNING[20818]: app_voicemail.c:6152 vm_authenticate: Unable to read password butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: app_voicemail.c:6317 vm_execmain: After vm_authenticate butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:2310 __ast_pbx_run: Extension 86, priority 1 returned normally even though call was hung up butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"ext12" <12>' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '12' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '86' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'longdistance' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/12-081bcf00' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'VoiceMailMain' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-01 20:30:01' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-01 20:30:01' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-02-01 20:30:18' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '17' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '17' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1170351001.13' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: channel.c:1589 ast_hangup: Hanging up channel 'SIP/12-081bcf00' butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:3420 sip_hangup: Hangup call SIP/12-081bcf00, SIP callid 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan) butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:3428 sip_hangup: update_call_counter(12) - decrement call limit counter on hangup butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:3128 update_call_counter: Updating call counter for incoming call butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/12-081bcf00 butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: devicestate.c:371 do_state_change: Changing state for SIP/12 - state 1 (Not in use) butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 butthead*CLI> [Feb 1 20:30:18] DEBUG[20818]: app_queue.c:568 changethread: Device 'SIP/12' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. butthead*CLI> Really destroying SIP dialog '10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan' Method: BYE butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10895 sip_dump_history: ---------- SIP HISTORY for '10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan' butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10899 sip_dump_history: * SIP Call butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 001. Rx INVITE / 1 INVITE / sip:86@butthead.lan;transport=UDP butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 002. AuthChal Auth challenge sent for - nc 0 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 003. TxRespRel SIP/2.0 / 1 INVITE - 401 Unauthorized butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 004. SchedDestroy 32000 ms butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 005. Rx ACK / 1 ACK / sip:86@butthead.lan;transport=UDP butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 006. Rx INVITE / 2 INVITE / sip:86@butthead.lan;transport=UDP butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 007. CancelDestroy butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 008. Invite New call: 10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@but butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 009. AuthOK Auth challenge succesful for 12 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 010. NewChan Channel SIP/12-081bcf00 - from 10199880-2105a8c0-2710-45c22399- butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 011. TxResp SIP/2.0 / 2 INVITE - 100 Trying butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 012. TxRespRel SIP/2.0 / 2 INVITE - 200 OK butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 013. Rx ACK / 2 ACK / sip:86@192.168.5.77 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 014. Rx INFO / 3 INFO / sip:86@192.168.5.77 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 015. TxResp SIP/2.0 / 3 INFO - 415 Unsupported media type butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 016. Rx INFO / 4 INFO / sip:86@192.168.5.77 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 017. TxResp SIP/2.0 / 4 INFO - 415 Unsupported media type butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 018. Rx INFO / 5 INFO / sip:86@192.168.5.77 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 019. TxResp SIP/2.0 / 5 INFO - 415 Unsupported media type butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 020. Rx BYE / 6 BYE / sip:86@192.168.5.77 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 021. RTCPaudio Quality:ssrc=619332208;themssrc=3959242945;lp=0;rxjitter=0.0000 butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 022. TxResp SIP/2.0 / 6 BYE - 200 OK butthead*CLI> [Feb 1 20:30:19] DEBUG[20818]: chan_sip.c:10905 sip_dump_history: ---------- END SIP HISTORY for '10199880-2105a8c0-2710-45c22399-2c0c31e6-45c22399@butthead.lan'