Intermittent failures with mpd VPN

Jeff Leary quixoticsycophant at yahoo.com
Wed Aug 20 22:06:26 PDT 2003


Hi,

I have a 4.5-release firewall / VPN server which has been humming along
without a glitch since 4.5-release first came out.

I have applied only relevant patches during this time since this box's
only job is ipfilter, ipnat, and mpd.

Just recently there's been this intermittent behavior of not being able
to login -- but if you keep trying you'll eventually get in after 4 or
5
attempts.

Failed logins look like

 PPTP connection from 1.2.3.4:1705 
 pptp0: attached to connection with 1.2.3.4:1705 
 [pptp0] IFACE: Open event 
 [pptp0] IPCP: Open event 
 [pptp0] IPCP: state change Initial --> Starting 
 [pptp0] IPCP: LayerStart 
 [pptp0] IPCP: Open event 
 [pptp0] bundle: OPEN event in state CLOSED 
 [pptp0] opening link "pptp0"... 
 [pptp0] link: OPEN event 
 [pptp0] LCP: Open event 
 [pptp0] LCP: state change Initial --> Starting 
 [pptp0] LCP: LayerStart 
 [pptp0] device: OPEN event in state DOWN 
 [pptp0] attaching to peer's outgoing call 
 [pptp0] device is now in state OPENING 
 [pptp0] device: UP event in state OPENING 
 [pptp0] device is now in state UP 
 [pptp0] link: UP event 
 [pptp0] link: origination is remote 
 [pptp0] LCP: Up event 
 [pptp0] LCP: state change Starting --> Req-Sent 
 [pptp0] LCP: phase shift DEAD --> ESTABLISH 
 [pptp0] LCP: SendConfigReq #50 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 pptp0-0: ignoring SetLinkInfo 
 [pptp0] LCP: rec'd Configure Request #0 link 0 (Req-Sent) 
  MAGICNUM 3b27257f 
  PROTOCOMP 
  ACFCOMP 
  CALLBACK 
    Not supported 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigRej #0 
  CALLBACK 
 [pptp0] LCP: SendConfigReq #51 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: rec'd Configure Request #1 link 0 (Req-Sent) 
  MAGICNUM 3b27257f 
  PROTOCOMP 
  ACFCOMP 
  CALLBACK 
    Not supported 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigRej #1 
  CALLBACK 
 [pptp0] LCP: SendConfigReq #52 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: rec'd Configure Request #2 link 0 (Req-Sent) 
  MAGICNUM 3b27257f 
  PROTOCOMP 
  ACFCOMP 
  CALLBACK 
    Not supported 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigRej #2 
  CALLBACK 
 [pptp0] LCP: SendConfigReq #53 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: SendConfigReq #54 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: rec'd Configure Request #3 link 0 (Req-Sent) 
  MAGICNUM 3b27257f 
  PROTOCOMP 
  ACFCOMP 
  CALLBACK 
    Not supported 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigRej #3 
  CALLBACK 
 [pptp0] LCP: SendConfigReq #55 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: SendConfigReq #56 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: rec'd Configure Request #4 link 0 (Req-Sent) 
  MAGICNUM 3b27257f 
  PROTOCOMP 
  ACFCOMP 
  CALLBACK 
    Not supported 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigRej #4 
  CALLBACK 
 [pptp0] LCP: SendConfigReq #57 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: SendConfigReq #58 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 88c318a0 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: rec'd Configure Request #5 link 0 (Req-Sent) 
  MAGICNUM 3b27257f 
  PROTOCOMP 
  ACFCOMP 
  CALLBACK 
    Not supported 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: not converging 
 [pptp0] LCP: parameter negotiation failed 
 [pptp0] LCP: state change Req-Sent --> Stopped 
 [pptp0] LCP: LayerFinish 
 [pptp0] device: CLOSE event in state UP 
 pptp0-0: clearing call 
 pptp0-0: killing channel 
 [pptp0] PPTP call terminated 
 [pptp0] IFACE: Close event 
 [pptp0] IPCP: Close event 
 [pptp0] IPCP: state change Starting --> Initial 
 [pptp0] IPCP: LayerFinish 
 [pptp0] IFACE: Close event 
 pptp0: closing connection with 1.2.3.4:1705 
 [pptp0] IFACE: Close event 
 [pptp0] device is now in state CLOSING 
 [pptp0] bundle: CLOSE event in state OPENED 
 [pptp0] closing link "pptp0"... 
 [pptp0] device: DOWN event in state CLOSING 
 [pptp0] device is now in state DOWN 
 [pptp0] link: CLOSE event 
 [pptp0] LCP: Close event 
 [pptp0] LCP: state change Stopped --> Closed 
 [pptp0] device: DOWN event in state DOWN 
 [pptp0] device is now in state DOWN 
 [pptp0] link: DOWN event 
 [pptp0] LCP: Down event 
 [pptp0] LCP: state change Closed --> Initial 
 [pptp0] LCP: phase shift ESTABLISH --> DEAD 
 [pptp0] link: DOWN event 
 [pptp0] LCP: Down event 
 pptp0: killing connection with 1.2.3.4:1705 

successful logins look like

 PPTP connection from 1.2.3.4:2738 
 pptp0: attached to connection with 1.2.3.4:2738 
 [pptp0] IFACE: Open event 
 [pptp0] IPCP: Open event 
 [pptp0] IPCP: state change Initial --> Starting 
 [pptp0] IPCP: LayerStart 
 [pptp0] IPCP: Open event 
 [pptp0] bundle: OPEN event in state CLOSED 
 [pptp0] opening link "pptp0"... 
 [pptp0] link: OPEN event 
 [pptp0] LCP: Open event 
 [pptp0] LCP: state change Initial --> Starting 
 [pptp0] LCP: LayerStart 
 [pptp0] device: OPEN event in state DOWN 
 [pptp0] attaching to peer's outgoing call 
 [pptp0] device is now in state OPENING 
 [pptp0] device: UP event in state OPENING 
 [pptp0] device is now in state UP 
 [pptp0] link: UP event 
 [pptp0] link: origination is remote 
 [pptp0] LCP: Up event 
 [pptp0] LCP: state change Starting --> Req-Sent 
 [pptp0] LCP: phase shift DEAD --> ESTABLISH 
 [pptp0] LCP: SendConfigReq #59 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 89dadabc 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  MP SHORTSEQ 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 pptp0-0: ignoring SetLinkInfo 
 [pptp0] LCP: rec'd Configure Request #0 link 0 (Req-Sent) 
  MAGICNUM 47f55acf 
  PROTOCOMP 
  ACFCOMP 
  CALLBACK 
    Not supported 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigRej #0 
  CALLBACK 
 [pptp0] LCP: rec'd Configure Reject #59 link 0 (Req-Sent) 
  MP SHORTSEQ 
 [pptp0] LCP: SendConfigReq #60 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 89dadabc 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: rec'd Configure Request #1 link 0 (Req-Sent) 
  MAGICNUM 47f55acf 
  PROTOCOMP 
  ACFCOMP 
  MP MRRU 1614 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigNak #1 
  MP MRRU 1600 
 [pptp0] LCP: rec'd Configure Ack #60 link 0 (Req-Sent) 
  ACFCOMP 
  PROTOCOMP 
  MRU 1500 
  MAGICNUM 89dadabc 
  AUTHPROTO CHAP MSOFTv2 
  MP MRRU 1600 
  ENDPOINTDISC [802.1] 00 10 4b 06 de cf 
 [pptp0] LCP: state change Req-Sent --> Ack-Rcvd 
 [pptp0] LCP: rec'd Configure Request #2 link 0 (Ack-Rcvd) 
  MAGICNUM 47f55acf 
  PROTOCOMP 
  ACFCOMP 
  MP MRRU 1600 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: SendConfigAck #2 
  MAGICNUM 47f55acf 
  PROTOCOMP 
  ACFCOMP 
  MP MRRU 1600 
  ENDPOINTDISC [LOCAL] <MAC address snipped>
 [pptp0] LCP: state change Ack-Rcvd --> Opened 
 [pptp0] LCP: phase shift ESTABLISH --> AUTHENTICATE 
 [pptp0] LCP: auth: peer wants nothing, I want CHAP 
 [pptp0] CHAP: sending CHALLENGE 
 [pptp0] LCP: LayerUp 
 [pptp0] LCP: rec'd Ident #3 link 0 (Opened) 
  MESG: MSRASV5.00 
 [pptp0] LCP: rec'd Ident #4 link 0 (Opened) 
  MESG: MSRAS-1-ARDA 
 [pptp0] CHAP: rec'd RESPONSE #1 
  Name: "SOMEDOMAIN\somename" 
  Peer name: "somename" 
  Response is valid 
 [pptp0] CHAP: sending SUCCESS 
 [pptp0] LCP: authorization successful 
 [pptp0] LCP: phase shift AUTHENTICATE --> NETWORK 
 [pptp0] up: 1 link, total bandwidth 64000 bps 
 [pptp0] IPCP: Up event 
 [pptp0] IPCP: state change Starting --> Req-Sent 
 [pptp0] IPCP: SendConfigReq #3 
  IPADDR 192.168.1.1 
  COMPPROTO VJCOMP, 16 comp. channels, no comp-cid 
 [pptp0] error writing len 20 frame to bypass: Network is down 
 [pptp0] CCP: Open event 
 [pptp0] CCP: state change Initial --> Starting 
 [pptp0] CCP: LayerStart 
 [pptp0] CCP: Up event 
 [pptp0] CCP: state change Starting --> Req-Sent 
 [pptp0] CCP: SendConfigReq #2 
  MPPC 
    0x01000040: MPPE, 128 bit, stateless 
 [pptp0] error writing len 14 frame to bypass: Network is down 
 pptp0-0: ignoring SetLinkInfo 
 [pptp0] CCP: rec'd Configure Request #5 link 0 (Req-Sent) 
  MPPC 
    0x01000041: MPPC MPPE, 128 bit, stateless 
 [pptp0] CCP: SendConfigNak #5 
  MPPC 
    0x01000040: MPPE, 128 bit, stateless 
 [pptp0] IPCP: rec'd Configure Request #6 link 0 (Req-Sent) 
  IPADDR 0.0.0.0 
    NAKing with 192.168.1.206 
 [pptp0] IPCP: SendConfigNak #6 
  IPADDR 192.168.1.206 
 [pptp0] CCP: rec'd Configure Request #7 link 0 (Req-Sent) 
  MPPC 
    0x01000040: MPPE, 128 bit, stateless 
 [pptp0] CCP: SendConfigAck #7 
  MPPC 
    0x01000040: MPPE, 128 bit, stateless 
 [pptp0] CCP: state change Req-Sent --> Ack-Sent 
 [pptp0] IPCP: rec'd Configure Request #8 link 0 (Req-Sent) 
  IPADDR 192.168.1.206 
    192.168.1.206 is OK 
 [pptp0] IPCP: SendConfigAck #8 
  IPADDR 192.168.1.206 
 [pptp0] IPCP: state change Req-Sent --> Ack-Sent 
 [pptp0] IPCP: SendConfigReq #4 
  IPADDR 192.168.1.1 
  COMPPROTO VJCOMP, 16 comp. channels, no comp-cid 
 [pptp0] CCP: SendConfigReq #3 
  MPPC 
    0x01000040: MPPE, 128 bit, stateless 
 [pptp0] IPCP: rec'd Configure Reject #4 link 0 (Ack-Sent) 
  COMPPROTO VJCOMP, 16 comp. channels, no comp-cid 
 [pptp0] IPCP: SendConfigReq #5 
  IPADDR 192.168.1.1 
 [pptp0] CCP: rec'd Configure Ack #3 link 0 (Ack-Sent) 
  MPPC 
    0x01000040: MPPE, 128 bit, stateless 
 [pptp0] CCP: state change Ack-Sent --> Opened 
 [pptp0] CCP: LayerUp 
   Compress using: MPPE, 128 bit, stateless 
 Decompress using: MPPE, 128 bit, stateless 
 [pptp0] IPCP: rec'd Configure Ack #5 link 0 (Ack-Sent) 
  IPADDR 192.168.1.1 
 [pptp0] IPCP: state change Ack-Sent --> Opened 
 [pptp0] IPCP: LayerUp 
   192.168.1.1 -> 192.168.1.206 
 [pptp0] IFACE: Up event 
 [pptp0] exec: /sbin/ifconfig ng0 192.168.1.1 192.168.1.206 netmask
0xffffffff -link0 
 [pptp0] exec: /usr/sbin/arp -s 192.168.1.206 0:10:4b:6:de:cf pub 
 [pptp0] IFACE: Up event 

One difference being repeated cycles of "CALLBACK not supported" for
the failed login and only one instance of "CALLBACK not supported"
for the sucessful login.

The two attempts shown above were 5 minutes apart with absolutely no
changes being made to the client or server.

The generic reason here is a hardware failure.  Indeed, this box was
someone's workstation for a couple years before it became a VPN server.

However, I am hoping in a very serious way that there is another
explanation.  Any ideas?

Thanks,
Jeff





__________________________________
Do you Yahoo!?
Yahoo! SiteBuilder - Free, easy-to-use web site design software
http://sitebuilder.yahoo.com


More information about the freebsd-questions mailing list