Date: Sun, 16 May 2010 14:58:00 -0700 From: "Crist J. Clark" <cristclark@comcast.net> To: net@freebsd.org Subject: MPD Just Stopped Working? Message-ID: <20100516215759.GA53824@goku.i.pumpky.net>
next in thread | raw e-mail | index | archive | help
I'm running mpd5 on 7.2-RELEASE-p5. I just use it to tunnel from a Windows XP machine to the MPD server over an insecure (wireless) network. It "just stopped working" Friday. The MPD configuration hasn't been touched. As far as I know, nothing on the Windows box has changed. I'd suspect something stealthily changed on the Windoze box by Windows Update or the AV (Norton) software, but the more I look at the problem, it looks like the MPD side. The connection comes up, I see the two machines talk over the network with the XP machine the last to talk to the MPD side. Then the MPD side seems to try to figure some things out with itself for a few seconds before failing and closing down the connection. Here's what a packet capture looks like, 14:48:12.322112 IP 192.168.128.253.2255 > 192.168.128.254.1723: S 2131756225:2131756225(0) win 16384 <mss 1260,nop,nop,sackOK> 14:48:12.322310 IP 192.168.128.254.1723 > 192.168.128.253.2255: S 4093488321:4093488321(0) ack 2131756226 win 65535 <mss 1260,sackOK,eol> 14:48:12.325435 IP 192.168.128.253.2255 > 192.168.128.254.1723: P 1:157(156) ack 1 win 17640: pptp CTRL_MSGTYPE=SCCRQ PROTO_VER(1.0) FRAME_CAP(A) BEARER_CAP(A) MAX_CHAN(0) FIRM_REV(2600) [|pptp] 14:48:12.326120 IP 192.168.128.254.1723 > 192.168.128.253.2255: P 1:157(156) ack 157 win 65535: pptp CTRL_MSGTYPE=SCCRP PROTO_VER(1.0) RESULT_CODE(1) ERR_CODE(0) FRAME_CAP(AS) BEARER_CAP(DA) MAX_CHAN(0) FIRM_REV(257) [|pptp] 14:48:12.326863 IP 192.168.128.253.2255 > 192.168.128.254.1723: P 157:325(168) ack 157 win 17484: pptp CTRL_MSGTYPE=OCRQ CALL_ID(49152) CALL_SER_NUM(62587) MIN_BPS(300) MAX_BPS(100000000) BEARER_TYPE(Any) FRAME_TYPE(E) RECV_WIN(64) PROC_DELAY(0) PHONE_NO_LEN(0) [|pptp] 14:48:12.329535 IP 192.168.128.254.1723 > 192.168.128.253.2255: P 157:189(32) ack 325 win 65535: pptp CTRL_MSGTYPE=OCRP CALL_ID(64971) PEER_CALL_ID(49152) RESULT_CODE(1) ERR_CODE(0) CAUSE_CODE(0) CONN_SPEED(64000) RECV_WIN(16) PROC_DELAY(1) PHY_CHAN_ID(0) 14:48:12.337938 IP 192.168.128.253.2255 > 192.168.128.254.1723: P 325:349(24) ack 189 win 17452: pptp CTRL_MSGTYPE=SLI PEER_CALL_ID(64971) SEND_ACCM(0xffffffff) RECV_ACCM(0xffffffff) 14:48:12.437639 IP 192.168.128.254.1723 > 192.168.128.253.2255: . ack 349 win 65535 14:48:29.343757 IP 192.168.128.254.1723 > 192.168.128.253.2255: P 189:337(148) ack 349 win 65535: pptp CTRL_MSGTYPE=CDN CALL_ID(64971) RESULT_CODE(3) ERR_CODE(0) CAUSE_CODE(0) [|pptp] 14:48:29.345175 IP 192.168.128.253.2255 > 192.168.128.254.1723: P 349:365(16) ack 337 win 17304: pptp CTRL_MSGTYPE=StopCCRQ REASON(1) 14:48:29.345629 IP 192.168.128.254.1723 > 192.168.128.253.2255: P 337:353(16) ack 365 win 65535: pptp CTRL_MSGTYPE=StopCCRP RESULT_CODE(1) ERR_CODE(0) 14:48:29.345763 IP 192.168.128.254.1723 > 192.168.128.253.2255: F 353:353(0) ack 365 win 65535 14:48:29.346531 IP 192.168.128.253.2255 > 192.168.128.254.1723: F 365:365(0) ack 354 win 17288 14:48:29.346637 IP 192.168.128.254.1723 > 192.168.128.253.2255: . ack 366 win 65534 And here is are the logs from MPD that correspond to this connection. Note all of the MPD activity between the hole in the packet capture from 14:48:12 to 14:48:29. It seems the server is having problems negotiating with itself? May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] Link: OPEN event May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: Open event May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: state change Initial --> Starting May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: LayerStart May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] PPTP: attaching to peer's outgoing call May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] Link: UP event May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] Link: origination is remote May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: Up event May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: state change Starting --> Req-Sent May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #1 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: rec'd Configure Request #0 (Req-Sent) May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] MRU 1400 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5e8514f4 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigRej #0 May 16 14:48:12 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #2 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] LCP: rec'd Configure Request #1 (Req-Sent) May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] MRU 1400 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5e8514f4 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigRej #1 May 16 14:48:14 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #3 May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:16 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] LCP: rec'd Configure Request #2 (Req-Sent) May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] MRU 1400 May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5e8514f4 May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigRej #2 May 16 14:48:17 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #4 May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:18 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #5 May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:20 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] LCP: rec'd Configure Request #3 (Req-Sent) May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] MRU 1400 May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5e8514f4 May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigRej #3 May 16 14:48:21 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #6 May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:22 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #7 May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:24 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] LCP: rec'd Configure Request #4 (Req-Sent) May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] MRU 1400 May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5e8514f4 May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigRej #4 May 16 14:48:25 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #8 May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:26 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] LCP: SendConfigReq #9 May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] MRU 1500 May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5ae3249c May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] AUTHPROTO CHAP MSOFTv2 May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] MP MRRU 2048 May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] MP SHORTSEQ May 16 14:48:28 <daemon.info> net5501 mpd: [L-1] ENDPOINTDISC [802.1] 00 00 24 ca 91 b4 May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: rec'd Configure Request #5 (Req-Sent) May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] MRU 1400 May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] MAGICNUM 5e8514f4 May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] PROTOCOMP May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] ACFCOMP May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] CALLBACK 6 May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: not converging May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: parameter negotiation failed May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: state change Req-Sent --> Stopped May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: LayerFinish May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] PPTP call terminated May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] Link: DOWN event May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: Close event May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: state change Stopped --> Closed May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: Down event May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] LCP: state change Closed --> Initial May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] Link: SHUTDOWN event May 16 14:48:29 <daemon.info> net5501 mpd: [L-1] Link: Shutdown -- Crist J. Clark | cjclark@alum.mit.edu
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20100516215759.GA53824>