Vyos1.1.8 the problem fo "PPTP+Radius"


#1
  1. I test “L2TP+Radius”,it’s ok;
  2. I test “PPTP+Localuser”,it’s ok;
  3. I test “PPTP+Radius”,There is some problem;

the vyos config:

pptp {
remote-access {
authentication {
local-users {
username fei.xue {
password ****************
}
}
mode radius
radius-server 10.131.2.13 {
key ****************
}
require mschap-v2
}
client-ip-pool {
start 10.131.57.20
stop 10.131.57.220
}
dns-servers {
server-1 10.131.2.9
}
outside-address 114.112.84.201
}

the windows PPTP client:
image

the error log :

2018-12-05 10:49:01 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: MGR: Launching /usr/sbin/pptpctrl to handle client
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: local address = 10.255.254.0
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: remote address = 10.131.57.20
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: pppd options file = /etc/ppp/options.pptpd
2018-12-05 10:49:02 Daemon.Info 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Client 118.186.39.90 control connection started
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Received PPTP Control Message (type: 1)
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Made a START CTRL CONN RPLY packet
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: I wrote 156 bytes to the client.
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Sent packet to client
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Received PPTP Control Message (type: 7)
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Set parameters to 100000000 maxbps, 64 window size
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Made a OUT CALL RPLY packet
2018-12-05 10:49:02 Daemon.Info 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Starting call (launching pppd, opening GRE)
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: pty_fd = 6
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: tty_fd = 7
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: I wrote 32 bytes to the client.
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Sent packet to client
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17561]: CTRL (PPPD Launcher): program binary = /usr/sbin/pppd
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17561]: CTRL (PPPD Launcher): local address = 10.255.254.0
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17561]: CTRL (PPPD Launcher): remote address = 10.131.57.20
2018-12-05 10:49:02 Local2.Info 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: Plugin radius.so loaded.
2018-12-05 10:49:02 Local2.Info 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: RADIUS plugin initialized.
2018-12-05 10:49:02 Local2.Info 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: Plugin radattr.so loaded.
2018-12-05 10:49:02 Local2.Info 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: RADATTR plugin initialized.
2018-12-05 10:49:02 Local2.Notice 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: pppd 2.4.4 started by root, uid 0
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: using channel 81
2018-12-05 10:49:02 Local7.Info 10.131.2.39 Dec 5 10:48:46 vpn39 zebra[2429]: interface ppp0 index 84 <POINTOPOINT,NOARP,MULTICAST> added.
2018-12-05 10:49:02 Local2.Info 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: Using interface ppp0
2018-12-05 10:49:02 Local2.Notice 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: Connect: ppp0 <–> /dev/pts/1
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x7778e3d0> ]
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Received PPTP Control Message (type: 15)
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: CTRL: Got a SET LINK INFO packet with standard ACCMs
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: GRE: accepting packet #0
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: rcvd [LCP ConfReq id=0x0 <mru 1400> <magic 0x14a1d81> ]
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: lcp_reqci: rcvd unknown option 13
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: lcp_reqci: returning CONFREJ.
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: sent [LCP ConfRej id=0x0 ]
2018-12-05 10:49:02 Daemon.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pptpd[17559]: GRE: accepting packet #1
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: rcvd [LCP ConfReq id=0x1 <mru 1400> <magic 0x14a1d81> ]
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: lcp_reqci: returning CONFACK.
2018-12-05 10:49:02 Local2.Debug 10.131.2.39 Dec 5 10:48:46 vpn39 pppd[17561]: sent [LCP ConfAck id=0x1 <mru 1400> <magic 0x14a1d81> ]
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x7778e3d0> ]
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #2
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x7778e3d0> ]
2018-12-05 10:49:05 Local7.Info 10.131.2.39 Dec 5 10:48:49 vpn39 zebra[2429]: interface ppp0 mtu changed from 1500 to 1400
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Received PPTP Control Message (type: 15)
2018-12-05 10:49:05 Daemon.Error 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #3
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: sent [CHAP Challenge id=0x27 , name = “pptpd”]
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #4
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #5
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [LCP Ident id=0x2 magic=0x14a1d81 “MSRASV5.20”]
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [LCP Ident id=0x3 magic=0x14a1d81 “MSRAS-0-KVM-ADMIN-IP19”]
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [LCP Ident id=0x4 magic=0x14a1d81 “!\37777777764\37777777765z\37777777710\37777777610\021@\37777777627\37777777660\031\37777777634\37777777620\37777777765\37777777725\37777777702”]
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #6
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [CHAP Response id=0x27 , name = “fei.xue”]
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: RADATTR plugin wrote 7 line(s) to file /var/run/radattr.ppp0.
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: sent [CHAP Success id=0x27 “S=CB3ADAC337F4E3B84ACBAF62EAFF264BD14061D3”]
2018-12-05 10:49:05 Local2.Error 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: MPPE required, but keys are not available. Possible plugin problem?
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: sent [LCP TermReq id=0x2 “MPPE required but not available”]
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #7
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [proto=0x8057] 01 05 00 0e 01 0a a0 8a e5 72 50 9d 81 71
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: Discarded non-LCP packet when LCP not open 0 0
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #8
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [CCP ConfReq id=0x6 <mppe +H -M -S -L -D -C>]
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #9
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: Discarded non-LCP packet when LCP not open 0 0
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [IPCP ConfReq id=0x7 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-wins 0.0.0.0> <ms-dns3 0.0.0.0> <ms-wins 0.0.0.0>]
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: Discarded non-LCP packet when LCP not open 0 0
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Received PPTP Control Message (type: 15)
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Got a SET LINK INFO packet with standard ACCMs
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: GRE: accepting packet #10
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: rcvd [LCP TermAck id=0x2 “MPPE required but not available”]
2018-12-05 10:49:05 Local2.Notice 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: Connection terminated: no multilink.
2018-12-05 10:49:05 Local2.Info 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: Connect time 0.1 minutes.
2018-12-05 10:49:05 Local2.Info 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: Sent 0 bytes, received 0 bytes.
2018-12-05 10:49:05 Local7.Info 10.131.2.39 Dec 5 10:48:49 vpn39 zebra[2429]: interface ppp0 index 84 deleted.
2018-12-05 10:49:05 Local7.Info 10.131.2.39 Dec 5 10:48:49 vpn39 ripngd[2433]: interface delete ppp0 index 84 flags 0x1090 metric 1 mtu 1400
2018-12-05 10:49:05 Local7.Info 10.131.2.39 Dec 5 10:48:49 vpn39 ripd[2431]: interface delete ppp0 index 84 flags 0x1090 metric 1 mtu 1400
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Received PPTP Control Message (type: 12)
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Made a CALL DISCONNECT RPLY packet
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Received CALL CLR request (closing call)
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Reaping child PPP[17561]
2018-12-05 10:49:05 Local2.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: RADATTR plugin removed file /var/run/radattr.ppp0.
2018-12-05 10:49:05 Local2.Info 10.131.2.39 Dec 5 10:48:49 vpn39 pppd[17561]: Exit.
2018-12-05 10:49:05 Daemon.Info 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Client 118.186.39.90 control connection finished
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[17559]: CTRL: Exiting now
2018-12-05 10:49:05 Daemon.Debug 10.131.2.39 Dec 5 10:48:49 vpn39 pptpd[12930]: MGR: Reaped child 17559