Dear Stefan! This is the log of the firewall for an unsuccessful connection: 2017-01-05 15:35:23 accel-pppd msg=:: recv [L2TP tid=0 sid=0 Ns=0 Nr=0 <Message-Type Start-Ctrl-Conn-Request> <Protocol-Version 256> <Framing-Capabilities 3> <Host-Name Peters-iPad> <Assigned-Tunnel-ID 34> <Recv-Window-Size 4>] Debug 2017-01-05 15:35:23 accel-pppd msg=:: send [L2TP tid=34 sid=0 Ns=0 Nr=1 <Message-Type Start-Ctrl-Conn-Reply> <Protocol-Version 256> <Host-Name POW1> <Framing-Capabilities 3> <Assigned-Tunnel-ID 1> <Vendor-Name accel-ppp>] Debug 2017-01-05 15:35:23 accel-pppd msg=:: recv [L2TP tid=1 sid=0 Ns=1 Nr=1 <Message-Type Start-Ctrl-Conn-Connected>] Debug 2017-01-05 15:35:23 accel-pppd msg=:: recv [L2TP tid=1 sid=0 Ns=2 Nr=1 <Message-Type Incoming-Call-Request> <Assigned-Session-ID 332> <Call-Serial-Number 1>] Debug 2017-01-05 15:35:23 accel-pppd msg=:: send [L2TP tid=34 sid=332 Ns=1 Nr=3 <Message-Type Incoming-Call-Reply> <Assigned-Session-ID 1>] Debug 2017-01-05 15:35:23 accel-pppd msg=:: recv [L2TP tid=1 sid=1 Ns=3 Nr=2 <Message-Type Incoming-Call-Connected> <TX-Speed 1000000> <Framing-Type 3>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: connect: ppp0 <--> l2tp( 89.212.168.xyz) Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: lcp_layer_init Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: auth_layer_init Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: ccp_layer_init Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: ipcp_layer_init Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: ipv6cp_layer_init Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: ppp established Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: lcp_layer_start Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: send [LCP ConfReq id=1 <auth MSCHAP-v2> <magic 2df6d648> <mru 1400>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: send [L2TP tid=34 sid=0 Ns=2 Nr=4] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: recv [LCP ConfReq id=1 < 2 6 0 0 0 0 > <magic 57044e1e> <pcomp> <accomp>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: send [LCP ConfRej id=1 < 2 6 0 0 0 0 > <pcomp> <accomp>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: recv [LCP ConfAck id=1 <auth MSCHAP-v2> <magic 2df6d648> <mru 1400>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: recv [LCP ConfReq id=2 <magic 57044e1e>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: send [LCP ConfAck id=2 ] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: lcp_layer_started Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: auth_layer_start Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: send [MSCHAP-v2 Challenge id=1 <9db289b1154a96a74592f6278d5fbbc>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: recv [LCP EchoReq id=0 <magic 57044e1e>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: send [LCP EchoRep id=0 <magic 48d6f62d>] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: recv [MSCHAP-v2 Response id=1 <9864eb6874e71568292ed3764e322a8>, <62eb71aa08cf141c9d171c92ae423c08d1822fdcb47f>, F=0, name="Peter Dudas"] Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: tpas: id:1 flags:0x0 reserved:0x33800a93 Debug 2017-01-05 15:35:23 accel-pppd msg=ppp0:: tpas: auth_hand started (pid 19780) Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:: tpas: auth_hnd finished (0) Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:: tpas: result:OKAY S=D00BCA794534EC5AB5EB766E9AFD0B681CEA998E,A=a55b40eb94e2e1b7374b96d443b97397,B=5bc402515bbe524b8d983712821dc3bf Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: send [MSCHAP-v2 Success id=1 "S=D00BCA794534EC5AB5EB766E9AFD0B681CEA998E M=Authentication succeeded"] Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: recv [MSCHAP-v2 Response id=1 <9864eb6874e71568292ed3764e322a8>, <62eb71aa08cf141c9d171c92ae423c08d1822fdcb47f>, F=0, name="Peter Dudas"] Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: tpas: id:1 flags:0x0 reserved:0x33800a93 Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: tpas: auth_hand started (pid 19782) Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: tpas: auth_hnd finished (0) Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: tpas: result:OKAY Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: send [MSCHAP-v2 Failure id=1 "9db289b1154a96a745920f6278d5fbbc M=Access denied"] Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: ppp_terminate Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: lcp_layer_finish Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: send [LCP TermReq id=3] Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: auth_layer_finish Debug 2017-01-05 15:35:27 accel-pppd msg=ppp0:Peter Dudas: auth_layer_finished Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: IPCP: discarding packet Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: IPV6CP: discarding packet Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: recv [LCP TermAck id=3] Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: lcp_layer_finished Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: lcp_layer_free Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: auth_layer_free Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: ccp_layer_free Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: ipcp_layer_free Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: ipv6cp_layer_free Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: ppp destablished Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: l2tp: ppp finished Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: l2tp: terminate (0, 0) Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:Peter Dudas: send [L2TP tid=34 sid=0 Ns=2 Nr=4 <Message-Type Stop-Ctrl-Conn-Notify> <Assigned-Tunnel-ID 1> <Result-Code>] Debug 2017-01-05 15:35:28 accel-pppd msg=ppp0:: disconnected Debug And this is the successful: 2017-01-05 15:34:26 accel-pppd msg=:: recv [L2TP tid=0 sid=0 Ns=0 Nr=0 <Message-Type Start-Ctrl-Conn-Request> <Protocol-Version 256> <Framing-Capabilities 3> <Host-Name Peters-iPad> <Assigned-Tunnel-ID 33> <Recv-Window-Size 4>] Debug 2017-01-05 15:34:26 accel-pppd msg=:: send [L2TP tid=33 sid=0 Ns=0 Nr=1 <Message-Type Start-Ctrl-Conn-Reply> <Protocol-Version 256> <Host-Name POW1> <Framing-Capabilities 3> <Assigned-Tunnel-ID 1> <Vendor-Name accel-ppp>] Debug 2017-01-05 15:34:26 accel-pppd msg=:: recv [L2TP tid=1 sid=0 Ns=1 Nr=1 <Message-Type Start-Ctrl-Conn-Connected>] Debug 2017-01-05 15:34:26 accel-pppd msg=:: recv [L2TP tid=1 sid=0 Ns=2 Nr=1 <Message-Type Incoming-Call-Request> <Assigned-Session-ID 329> <Call-Serial-Number 1>] Debug 2017-01-05 15:34:26 accel-pppd msg=:: send [L2TP tid=33 sid=329 Ns=1 Nr=3 <Message-Type Incoming-Call-Reply> <Assigned-Session-ID 1>] Debug 2017-01-05 15:34:26 accel-pppd msg=:: recv [L2TP tid=1 sid=1 Ns=3 Nr=2 <Message-Type Incoming-Call-Connected> <TX-Speed 1000000> <Framing-Type 3>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: connect: ppp0 <--> l2tp( 89.212.168.xyz) Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: lcp_layer_init Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: auth_layer_init Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: ccp_layer_init Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: ipcp_layer_init Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: ipv6cp_layer_init Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: ppp established Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: lcp_layer_start Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: send [LCP ConfReq id=1 <auth MSCHAP-v2> <magic 68ebc550> <mru 1400>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: send [L2TP tid=33 sid=0 Ns=2 Nr=4] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: recv [LCP ConfReq id=1 < 2 6 0 0 0 0 > <magic 568bf110> <pcomp> <accomp>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: send [LCP ConfRej id=1 < 2 6 0 0 0 0 > <pcomp> <accomp>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: recv [LCP ConfAck id=1 <auth MSCHAP-v2> <magic 68ebc550> <mru 1400>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: recv [LCP ConfReq id=2 <magic 568bf110>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: send [LCP ConfAck id=2 ] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: lcp_layer_started Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: auth_layer_start Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: send [MSCHAP-v2 Challenge id=1 <b8cbbfa020ddad1e20bc4060c7bccfbf>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: recv [LCP EchoReq id=0 <magic 568bf110>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: send [LCP EchoRep id=0 <magic 50c5eb68>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: recv [MSCHAP-v2 Response id=1 <f1b3381d9a30e73a1dbd579844e575d2>, <7371de3c435d275975f17eae3ec9d5755a86207626f6>, F=0, name="Peter Dudas"] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: tpas: id:1 flags:0x0 reserved:0x33800a93 Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: tpas: auth_hand started (pid 19749) Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: tpas: auth_hnd finished (0) Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:: tpas: result:OKAY S=A540183EFBE609F94EAD79D80707C8D5ADC5C03A,A=79ebb8ec3143d8deb34d66dbbd900d88,B=1695340260afd1034cc9289f4535c415 Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: send [MSCHAP-v2 Success id=1 "S=A540183EFBE609F94EAD79D80707C8D5ADC5C03A M=Authentication succeeded"] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: auth_layer_started Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: ccp_layer_start Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: ipcp_layer_start Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: send [IPCP ConfReq id=1 <addr 10.148.76.36>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: ipv6cp_layer_start Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: Peter Dudas: authentication succeeded Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: recv [IPCP ConfReq id=1 <addr 0.0.0.0> <dns1 0.0.0.0> <dns2 0.0.0.0>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: send [IPCP ConfNak id=1 <addr 10.148.76.45> <dns1 10.101.168.3> <dns2 10.101.168.35>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: IPV6CP: discarding packet Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: send [LCP ProtoRej id=3 <8057>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: recv [IPCP ConfAck id=1 <addr 10.148.76.36>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: recv [IPCP ConfReq id=2 <addr 10.148.76.45> <dns1 10.101.168.3> <dns2 10.101.168.35>] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: send [IPCP ConfAck id=2] Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: ipcp_layer_started Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: l2tp: ppp started Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: tpas: ip-up started (pid 19751) Debug 2017-01-05 15:34:26 accel-pppd msg=ppp0:Peter Dudas: tpas: ip-up finished (0) Debug So it looks like a failed MsChapv2 authentication - which does not makes sense... It is the same mschap module with ntlm_auth. Does the challenge/response packets have a timeout? Peter Dudas On 5 January 2017 at 14:14, Stefan Paetow <Stefan.Paetow@jisc.ac.uk> wrote:
I'm not aware of any timing limitations (as with the SSLVPN I can even wait for 30s using the same 2nd authentication as for L2TP) - the whole chain (firewall-Nps-Freeradius) has minimum 30s timeout configured.
Ok... If 30 seconds is not enough, that is a bit of a concern.
With 'Sleep 3' it is still connected successfully - anything above 3 seconds just makes the L2TP VPN connection unsuccessful. Checked in the firewall - timeout is 90s.
You might want to check what the complete end-to-end timing is...
Stefan Paetow Moonshot Industry & Research Liaison Coordinator
t: +44 (0)1235 822 125 gpg: 0x3FCE5142 xmpp: stefanp@jabber.dev.ja.net skype: stefan.paetow.janet
jisc.ac.uk
Jisc is a registered charity (number 1149740) and a company limited by guarantee which is registered in England under Company No. 5747339, VAT No. GB 197 0632 86. Jisc¹s registered office is: One Castlepark, Tower Hill, Bristol, BS2 0JA. T 0203 697 5800.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html