[Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 48]: INVITE sip:86@butthead.lan;transport=UDP SIP/2.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10191b38-2105a8c0-2710-45c23650-1c68292a-45c23650 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 25]: To: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 14]: CSeq: 1 INVITE [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c23650-7ea429d3-1726b96b [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 9]: Min-SE: 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 19]: Content-Length: 389 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 3]: v=0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 1 [ 37]: o=a0000 8647 6672 IN IP4 192.168.5.33 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 10]: s=SIP Call [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 3 [ 21]: c=IN IP4 192.168.5.33 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 4 [ 5]: t=0 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 5 [ 45]: m=audio 10056 RTP/AVP 8 101 0 2 21 23 22 18 4 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 9 [ 23]: a=rtpmap:2 G726-32/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 10 [ 24]: a=rtpmap:21 G726-40/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 11 [ 24]: a=rtpmap:23 G726-16/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 12 [ 24]: a=rtpmap:22 G726-24/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 13 [ 21]: a=rtpmap:18 G729/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 14 [ 20]: a=rtpmap:4 G723/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 16 [ 10]: a=sendrecv [Feb 1 21:49:52] DEBUG[20818]: acl.c:215 ast_apply_ha: ##### Testing 192.168.5.33 with 192.168.5.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2703 do_setnat: Setting NAT on RTP to Off [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2713 do_setnat: Setting NAT on UDPTL to Off [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4404 sip_alloc: Allocating new SIP dialog for 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan - INVITE (With RTP) [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:1739 parse_sip_options: Begin: parsing SIP "Supported: replaces,timer,100rel" [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:1747 parse_sip_options: Found SIP option: -replaces- [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:1753 parse_sip_options: Matched SIP option: replaces [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:1747 parse_sip_options: Found SIP option: -timer- [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:1753 parse_sip_options: Matched SIP option: timer [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:1747 parse_sip_options: Found SIP option: -100rel- [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:1753 parse_sip_options: Matched SIP option: 100rel [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:13462 handle_request_invite: Initializing initreq for method INVITE - callid 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2703 do_setnat: Setting NAT on RTP to Off [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2713 do_setnat: Setting NAT on UDPTL to Off [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 24]: SIP/2.0 401 Unauthorized [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c23650-7ea429d3-1726b96b;received=192.168.5.33;rport=10000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10191b38-2105a8c0-2710-45c23650-1c68292a-45c23650 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as79ccc5ed [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 14]: CSeq: 1 INVITE [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 74]: WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="493bb1a7" [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2029 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7951 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 45]: ACK sip:86@butthead.lan;transport=UDP SIP/2.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10191b38-2105a8c0-2710-45c23650-1c68292a-45c23650 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as79ccc5ed [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c23650-7ea429d3-1726b96b [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 50]: Contact: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 17]: Content-Length: 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 0]: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7951 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2139 __sip_ack: Stopping retransmission on '101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan' of Response 1: Match Found butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 48]: INVITE sip:86@butthead.lan;transport=UDP SIP/2.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10191b38-2105a8c0-2710-45c23650-1c68292a-45c23650 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 25]: To: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 14]: CSeq: 2 INVITE [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c23650-7ea429e7-6b8b9ef0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [167]: Authorization: Digest username="12",realm="asterisk",nonce="493bb1a7",uri="sip:86@butthead.lan;transport=UDP",response="7c3154e9dce2c76c43c4286c9ea2946d",algorithm=MD5 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 9]: Min-SE: 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 19]: Content-Length: 389 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 14 [ 0]: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 3]: v=0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 1 [ 37]: o=a0000 8647 6672 IN IP4 192.168.5.33 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 10]: s=SIP Call [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 3 [ 21]: c=IN IP4 192.168.5.33 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 4 [ 5]: t=0 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 5 [ 45]: m=audio 10056 RTP/AVP 8 101 0 2 21 23 22 18 4 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 9 [ 23]: a=rtpmap:2 G726-32/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 10 [ 24]: a=rtpmap:21 G726-40/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 11 [ 24]: a=rtpmap:23 G726-16/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 12 [ 24]: a=rtpmap:22 G726-24/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 13 [ 21]: a=rtpmap:18 G729/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 14 [ 20]: a=rtpmap:4 G723/8000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 15 [ 15]: a=fmtp:101 0-15 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 16 [ 10]: a=sendrecv [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:13462 handle_request_invite: Initializing initreq for method INVITE - callid 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2703 do_setnat: Setting NAT on RTP to Off [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2713 do_setnat: Setting NAT on UDPTL to Off [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:5201 process_sdp: T38 state changed to 0 on channel [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:5278 process_sdp: We're settling with these formats: 0x10c (ulaw|alaw|g729) [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:13543 handle_request_invite: Checking SIP call limits for device 12 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:3128 update_call_counter: Updating call counter for incoming call [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:3907 sip_new: *** Our native formats are 0x4 (ulaw) [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:3908 sip_new: *** Joint capabilities are 0x10c (ulaw|alaw|g729) [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:3909 sip_new: *** Our capabilities are 0x10c (ulaw|alaw|g729) [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:3910 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:3933 sip_new: This channel will not be able to handle video. [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:8012 build_route: build_route: Contact hop: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:13618 handle_request_invite: SIP/12-081bcf00: New call is still down.... Trying... [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c23650-7ea429e7-6b8b9ef0;received=192.168.5.33;rport=10000 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10191b38-2105a8c0-2710-45c23650-1c68292a-45c23650 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 25]: To: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 14]: CSeq: 2 INVITE [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 30]: Contact: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 21:49:52] 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 21:49:52] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 [Feb 1 21:49:52] DEBUG[20818]: devicestate.c:371 do_state_change: Changing state for SIP/12 - state 1 (Not in use) [Feb 1 21:49:52] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 butthead*CLI> [Feb 1 21:49:52] 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 21:49:52] DEBUG[20818]: app_voicemail.c:6234 vm_execmain: Before ast_answer butthead*CLI> [Feb 1 21:49:52] 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 21:49:52] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 [Feb 1 21:49:52] DEBUG[20818]: devicestate.c:371 do_state_change: Changing state for SIP/12 - state 1 (Not in use) [Feb 1 21:49:52] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:3569 sip_answer: SIP answering channel: SIP/12-081bcf00 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:6506 transmit_response_with_sdp: Setting framing from config on incoming call butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:6281 add_sdp: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: True butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:6282 add_sdp: ** Our prefcodec: 0x0 (nothing) butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:6407 add_sdp: -- Done with adding codecs to SDP butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:6451 add_sdp: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729) butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 14]: SIP/2.0 200 OK butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c23650-7ea429e7-6b8b9ef0;received=192.168.5.33;rport=10000 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 88]: From: "ext12";tag=10191b38-2105a8c0-2710-45c23650-1c68292a-45c23650 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 40]: To: ;tag=as3135ac64 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 71]: Call-ID: 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 14]: CSeq: 2 INVITE butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 30]: Contact: butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 29]: Content-Type: application/sdp butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 19]: Content-Length: 311 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 0]: butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 3]: v=0 butthead*CLI> [Feb 1 21:49:52] 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 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 9]: s=session butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 3 [ 21]: c=IN IP4 192.168.5.77 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 4 [ 5]: t=0 0 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 5 [ 32]: m=audio 17836 RTP/AVP 0 8 18 101 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 8 [ 21]: a=rtpmap:18 G729/8000 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 9 [ 19]: a=fmtp:18 annexb=no butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 10 [ 33]: a=rtpmap:101 telephone-event/8000 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 11 [ 15]: a=fmtp:101 0-16 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 12 [ 25]: a=silenceSupp:off - - - - butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 13 [ 10]: a=ptime:20 butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 14 [ 10]: a=sendrecv [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2029 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7953 [Feb 1 21:49:52] 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. [Feb 1 21:49:52] 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 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 31]: ACK sip:86@192.168.5.77 SIP/2.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 88]: From: "ext12";tag=10191b38-2105a8c0-2710-45c23650-1c68292a-45c23650 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 40]: To: ;tag=as3135ac64 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 71]: Call-ID: 101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 83]: Via: SIP/2.0/UDP 192.168.5.33:10000;rport;branch=z9hG4bK-45c23650-7ea42a05-744632b9 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 50]: Contact: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [167]: Authorization: Digest username="12",realm="asterisk",nonce="493bb1a7",uri="sip:86@butthead.lan;transport=UDP",response="7c3154e9dce2c76c43c4286c9ea2946d",algorithm=MD5 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7953 [Feb 1 21:49:52] DEBUG[20818]: chan_sip.c:2139 __sip_ack: Stopping retransmission on '101998c0-2105a8c0-2710-45c23650-765fd8fd-45c23650@butthead.lan' of Response 2: Match Found butthead*CLI> [Feb 1 21:49:52] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format alaw [Feb 1 21:49:52] DEBUG[20818]: rtp.c:2757 ast_rtp_write: Ooh, format changed from unknown to ulaw [Feb 1 21:49:52] 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 21:49:55] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format ulaw butthead*CLI> [Feb 1 21:49:56] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) [Feb 1 21:49:56] DEBUG[20818]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 192.168.5.33 [Feb 1 21:49:56] DTMF[20818]: channel.c:2162 __ast_read: DTMF begin '1' received on SIP/12-081bcf00 butthead*CLI> [Feb 1 21:49:56] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4) butthead*CLI> [Feb 1 21:49:56] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Feb 1 21:49:56] DEBUG[20818]: rtp.c:644 send_dtmf: Sending dtmf: 50 (2), at 192.168.5.33 [Feb 1 21:49:56] DTMF[20818]: channel.c:2162 __ast_read: DTMF begin '2' received on SIP/12-081bcf00 butthead*CLI> [Feb 1 21:49:57] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) butthead*CLI> [Feb 1 21:49:58] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Feb 1 21:49:58] DEBUG[20818]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 192.168.5.33 [Feb 1 21:49:58] DTMF[20818]: channel.c:2162 __ast_read: DTMF begin '#' received on SIP/12-081bcf00 butthead*CLI> [Feb 1 21:49:58] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) butthead*CLI> [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 47]: REGISTER sip:butthead.lan;transport=UDP SIP/2.0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 95]: From: ;tag=10190f30-2105a8c0-2710-45c23403-68d12b40-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 39]: To: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 58]: Call-ID: 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 16]: CSeq: 3 REGISTER [Feb 1 21:50: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-45c23659-7ea44cdd-1af7ab16 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 12]: Expires: 600 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [164]: Authorization: Digest username="12",realm="asterisk",nonce="2be88919",uri="sip:butthead.lan;transport=UDP",response="0ee138484e614022da4dcee2a6829011",algorithm=MD5 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 17]: Content-Length: 0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 21:50:01] DEBUG[20818]: acl.c:215 ast_apply_ha: ##### Testing 192.168.5.33 with 192.168.5.0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4404 sip_alloc: Allocating new SIP dialog for 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 - REGISTER (No RTP) [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:14636 handle_request_register: Initializing initreq for method REGISTER - callid 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c23659-7ea44cdd-1af7ab16;received=192.168.5.33;rport=10000 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 95]: From: ;tag=10190f30-2105a8c0-2710-45c23403-68d12b40-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 39]: To: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 58]: Call-ID: 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 16]: CSeq: 3 REGISTER [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 30]: Contact: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 24]: SIP/2.0 401 Unauthorized [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c23659-7ea44cdd-1af7ab16;received=192.168.5.33;rport=10000 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 95]: From: ;tag=10190f30-2105a8c0-2710-45c23403-68d12b40-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 54]: To: ;tag=as33fdd26a [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 58]: Call-ID: 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 16]: CSeq: 3 REGISTER [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 74]: WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="71c10998" [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: butthead*CLI> [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 47]: REGISTER sip:butthead.lan;transport=UDP SIP/2.0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 95]: From: ;tag=10190f30-2105a8c0-2710-45c23403-68d12b40-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 39]: To: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 58]: Call-ID: 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 16]: CSeq: 4 REGISTER [Feb 1 21:50: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-45c23659-7ea44cfb-507def32 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 32]: Supported: replaces,timer,100rel [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 31]: User-Agent: VTech ip8100 11.4.0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 50]: Contact: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 12]: Expires: 600 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [164]: Authorization: Digest username="12",realm="asterisk",nonce="71c10998",uri="sip:butthead.lan;transport=UDP",response="3fae5d22b9e9dd908e63527db6b48537",algorithm=MD5 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 17]: Content-Length: 0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:14751 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:14636 handle_request_register: Initializing initreq for method REGISTER - callid 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c23659-7ea44cfb-507def32;received=192.168.5.33;rport=10000 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 95]: From: ;tag=10190f30-2105a8c0-2710-45c23403-68d12b40-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 39]: To: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 58]: Call-ID: 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 16]: CSeq: 4 REGISTER [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 30]: Contact: [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 17]: Content-Length: 0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 0]: butthead*CLI> [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [111]: Via: SIP/2.0/UDP 192.168.5.33:10000;branch=z9hG4bK-45c23659-7ea44cfb-507def32;received=192.168.5.33;rport=10000 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 95]: From: ;tag=10190f30-2105a8c0-2710-45c23403-68d12b40-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 54]: To: ;tag=as33fdd26a [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 58]: Call-ID: 1019c998-2105a8c0-2710-45c23403-54a6907a-45c23403 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 16]: CSeq: 4 REGISTER [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 19]: Supported: replaces [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 12]: Expires: 600 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 62]: Contact: ;expires=600 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 35]: Date: Thu, 01 Feb 2007 18:50:01 GMT [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 17]: Content-Length: 0 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 13 [ 0]: [Feb 1 21:50:01] DEBUG[20818]: devicestate.c:387 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/12 butthead*CLI> [Feb 1 21:50:01] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 [Feb 1 21:50:01] DEBUG[20818]: devicestate.c:371 do_state_change: Changing state for SIP/12 - state 1 (Not in use) butthead*CLI> [Feb 1 21:50:01] DEBUG[20818]: devicestate.c:245 ast_device_state: No provider found, checking channel drivers for SIP - 12 [Feb 1 21:50:01] DEBUG[20818]: chan_sip.c:15367 sip_devicestate: Checking device state for peer 12 butthead*CLI> [Feb 1 21:50: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 21:50:05] DEBUG[20818]: app_voicemail.c:6141 vm_authenticate: Before find user for mailbox 12 [Feb 1 21:50:05] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format alaw [Feb 1 21:50:05] DEBUG[20818]: rtp.c:2626 ast_rtp_raw_write: Difference is 83808, ms is 10496 -- Playing 'vm-password' (language 'en') butthead*CLI> [Feb 1 21:50:06] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format ulaw butthead*CLI> [Feb 1 21:50:09] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) butthead*CLI> [Feb 1 21:50:09] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) butthead*CLI> [Feb 1 21:50:09] DEBUG[20818]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) butthead*CLI> [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4404 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Feb 1 21:50:10] DEBUG[20818]: acl.c:215 ast_apply_ha: ##### Testing 192.168.5.33 with 192.168.5.0 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:1679 initialize_initreq: Initializing initreq for method NOTIFY - callid 78c7c12816e27e4504fb9e253531613d@butthead.lan [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 54]: NOTIFY sip:12@192.168.5.33:10000;transport=UDP SIP/2.0 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.5.77:5060;branch=z9hG4bK73d3397c;rport [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as635129f8 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 45]: To: [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 36]: Contact: [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 54]: Call-ID: 78c7c12816e27e4504fb9e253531613d@butthead.lan [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 16]: CSeq: 102 NOTIFY [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 22]: Event: message-summary [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 48]: Content-Type: application/simple-message-summary [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 18]: Content-Length: 92 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 0]: [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 20]: Messages-Waiting: no [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 1 [ 42]: Message-Account: sip:asterisk@butthead.lan [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 24]: Voice-Message: 0/0 (0/0) [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 54]: NOTIFY sip:12@192.168.5.33:10000;transport=UDP SIP/2.0 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.5.77:5060;branch=z9hG4bK73d3397c;rport [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as635129f8 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 45]: To: [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 36]: Contact: [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 54]: Call-ID: 78c7c12816e27e4504fb9e253531613d@butthead.lan [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 16]: CSeq: 102 NOTIFY [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r52860 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 9 [ 22]: Event: message-summary [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 10 [ 48]: Content-Type: application/simple-message-summary [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 11 [ 18]: Content-Length: 92 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 12 [ 0]: [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 0 [ 20]: Messages-Waiting: no [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 1 [ 42]: Message-Account: sip:asterisk@butthead.lan [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Body 2 [ 24]: Voice-Message: 0/0 (0/0) [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:2029 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7959 butthead*CLI> [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 1 [ 58]: From: "asterisk";tag=as635129f8 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 2 [ 85]: To: ;tag=10192218-2105a8c0-2710-45c23662-43ddc8a3-45c23662 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 3 [ 54]: Call-ID: 78c7c12816e27e4504fb9e253531613d@butthead.lan [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 4 [ 16]: CSeq: 102 NOTIFY [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 5 [ 68]: Via: SIP/2.0/UDP 192.168.5.77:5060;rport=5060;branch=z9hG4bK73d3397c [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 6 [ 32]: Supported: replaces,timer,100rel [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 7 [ 17]: Content-Length: 0 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:4682 parse_request: Header 8 [ 0]: [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7959 [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:2139 __sip_ack: Stopping retransmission on '78c7c12816e27e4504fb9e253531613d@butthead.lan' of Request 102: Match Found Really destroying SIP dialog '78c7c12816e27e4504fb9e253531613d@butthead.lan' Method: NOTIFY [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:10895 sip_dump_history: ---------- SIP HISTORY for '78c7c12816e27e4504fb9e253531613d@butthead.lan' [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:10899 sip_dump_history: * SIP Call [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 001. SchedDestroy 32000 ms [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 002. TxReqRel NOTIFY / 102 NOTIFY - -UNKNOWN- [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:10902 sip_dump_history: 003. Rx SIP/2.0 / 102 NOTIFY / 200 OK [Feb 1 21:50:10] DEBUG[20818]: chan_sip.c:10905 sip_dump_history: ---------- END SIP HISTORY for '78c7c12816e27e4504fb9e253531613d@butthead.lan' butthead*CLI> -- Incorrect password '' for user '12' (context = default) [Feb 1 21:50:17] DEBUG[20818]: channel.c:2755 set_format: Set channel SIP/12-081bcf00 to write format alaw [Feb 1 21:50:17] DEBUG[20818]: rtp.c:2626 ast_rtp_raw_write: Difference is 83936, ms is 10512 -- Playing 'vm-incorrect-mailbox' (language 'en') butthead*CLI>