Actions
Bug #11761
open
L2TP/IPsec VPN : PPP LCP negotiation occurs before user authentication
Status:
New
Priority:
Normal
Assignee:
-
Category:
L2TP
Target version:
-
Start date:
03/31/2021
Due date:
% Done:
0%
Estimated time:
Plus Target Version:
Release Notes:
Default
Affected Version:
2.5.0
Affected Architecture:
Description
We are using pfSense to provide a l2tp/ipsec VPN connectivity to our users.
Users are using the Windows 10 (20h2) native VPN Client.
We have discovered that users only have about 20 seconds to type their user/password and submit the login form.
After that they receive an error : "the port used for this connection was closed"
Investigating the issue, it seems that PPP LCP negotiation starts as soon as the users clicks on "connect", not having yet provided his credentials.
Then, pfSense sends 10 LCP Configuration Requests with no response, so it closes the ESP child SA and destroy the IKE session.
Here is the log :
Mar 31 11:26:37 x.x.x.x charon: 09[NET] <8> received packet: from 80.80.80.80[36020] to 90.90.90.90[500] (408 bytes) <=== Client click on connect
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> parsed ID_PROT request 0 [ SA V V V V V V V V ]
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> looking for an IKEv1 config for 90.90.90.90...80.80.80.80
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> candidate: %any...%any, prio 24
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> candidate: %any...%any, prio 28
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> found matching ike config: %any...%any with prio 28
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> received unknown vendor ID: 01:52:8b:bb:c0:06:96:12:18:49:ab:9a:1c:5b:2a:51:00:00:00:01
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> received MS NT5 ISAKMPOAKLEY vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> received NAT-T (RFC 3947) vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> received FRAGMENTATION vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> received unknown vendor ID: fb:1d:e3:cd:f3:41:b7:ea:16:b7:e5:be:08:55:f1:20
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> received unknown vendor ID: 26:24:4d:38:ed:db:61:b3:17:2a:36:e3:d0:cf:b8:19
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> received unknown vendor ID: e3:a5:96:6a:76:37:9f:e7:07:22:82:31:e5:ce:86:52
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> 80.80.80.80 is initiating a Main Mode IKE_SA
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> IKE_SA (unnamed)[8] state change: CREATED => CONNECTING
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> selecting proposal:
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> no acceptable DIFFIE_HELLMAN_GROUP found
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> selecting proposal:
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> no acceptable ENCRYPTION_ALGORITHM found
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> selecting proposal:
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> proposal matches
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_384, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_256, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> sending XAuth vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> sending DPD vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> sending FRAGMENTATION vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> sending NAT-T (RFC 3947) vendor ID
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> generating ID_PROT response 0 [ SA V V V V ]
Mar 31 11:26:37 x.x.x.x charon: 09[NET] <8> sending packet: from 90.90.90.90[500] to 80.80.80.80[36020] (160 bytes)
Mar 31 11:26:37 x.x.x.x charon: 09[NET] <8> received packet: from 80.80.80.80[36020] to 90.90.90.90[500] (388 bytes)
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <8> remote host is behind NAT
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> candidate "bypasslan", match: 1/1/24 (me/other/ike)
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> candidate "con-mobile", match: 1/1/28 (me/other/ike)
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
Mar 31 11:26:37 x.x.x.x charon: 09[NET] <8> sending packet: from 90.90.90.90[500] to 80.80.80.80[36020] (372 bytes)
Mar 31 11:26:37 x.x.x.x charon: 09[NET] <8> received packet: from 80.80.80.80[44230] to 90.90.90.90[4500] (76 bytes)
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <8> parsed ID_PROT request 0 [ ID HASH ]
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> looking for pre-shared key peer configs matching 90.90.90.90...80.80.80.80[192.168.0.30]
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> candidate "bypasslan", match: 1/1/24 (me/other/ike)
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> candidate "con-mobile", match: 1/1/28 (me/other/ike)
Mar 31 11:26:37 x.x.x.x charon: 09[CFG] <8> selected peer config "con-mobile"
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <con-mobile|8> IKE_SA con-mobile[8] established between 90.90.90.90[90.90.90.90]...80.80.80.80[192.168.0.30]
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <con-mobile|8> IKE_SA con-mobile[8] state change: CONNECTING => ESTABLISHED
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <con-mobile|8> scheduling reauthentication in 28724s
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <con-mobile|8> maximum IKE_SA lifetime 28784s
Mar 31 11:26:37 x.x.x.x charon: 09[IKE] <con-mobile|8> DPD not supported by peer, disabled
Mar 31 11:26:37 x.x.x.x charon: 09[ENC] <con-mobile|8> generating ID_PROT response 0 [ ID HASH ]
Mar 31 11:26:37 x.x.x.x charon: 09[NET] <con-mobile|8> sending packet: from 90.90.90.90[4500] to 80.80.80.80[44230] (76 bytes)
Mar 31 11:26:37 x.x.x.x charon: 06[NET] <con-mobile|8> received packet: from 80.80.80.80[44230] to 90.90.90.90[4500] (444 bytes)
Mar 31 11:26:37 x.x.x.x charon: 06[ENC] <con-mobile|8> parsed QUICK_MODE request 1 [ HASH SA No ID ID NAT-OA NAT-OA ]
Mar 31 11:26:37 x.x.x.x charon: 06[IKE] <con-mobile|8> changing received traffic selectors 192.168.0.30/32|/0[udp/l2f]=== 90.90.90.90/32|/0[udp/l2f] due to NAT
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> looking for a child config for 90.90.90.90/32|/0[udp/l2f] === 80.80.80.80/32|/0[udp/l2f]
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> proposing traffic selectors for us:
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> 90.90.90.90/32|/0
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> proposing traffic selectors for other:
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> 80.80.80.80/32|/0
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> candidate "con-mobile" with prio 1+1
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> found matching child config "con-mobile" with prio 2
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> selecting traffic selectors for other:
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> config: 80.80.80.80/32|/0, received: 80.80.80.80/32|/0[udp/l2f] => match: 80.80.80.80/32|/0[udp/l2f]
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> selecting traffic selectors for us:
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> config: 90.90.90.90/32|/0, received: 90.90.90.90/32|/0[udp/l2f] => match: 90.90.90.90/32|/0[udp/l2f]
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> selecting proposal:
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> no acceptable ENCRYPTION_ALGORITHM found
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> selecting proposal:
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> proposal matches
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> received proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ, ESP:DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ, ESP:NULL/HMAC_SHA1_96/NO_EXT_SEQ
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> configured proposals: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
Mar 31 11:26:37 x.x.x.x charon: 06[CFG] <con-mobile|8> selected proposal: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
Mar 31 11:26:37 x.x.x.x charon: 06[IKE] <con-mobile|8> received 250000000 lifebytes, configured 0
Mar 31 11:26:37 x.x.x.x charon: 06[ENC] <con-mobile|8> generating QUICK_MODE response 1 [ HASH SA No ID ID NAT-OA NAT-OA ]
Mar 31 11:26:37 x.x.x.x charon: 06[NET] <con-mobile|8> sending packet: from 90.90.90.90[4500] to 80.80.80.80[44230] (204 bytes)
Mar 31 11:26:37 x.x.x.x charon: 06[NET] <con-mobile|8> received packet: from 80.80.80.80[44230] to 90.90.90.90[4500] (60 bytes)
Mar 31 11:26:37 x.x.x.x charon: 06[ENC] <con-mobile|8> parsed QUICK_MODE request 1 [ HASH ]
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> CHILD_SA con-mobile{5} state change: CREATED => INSTALLING
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> using AES_CBC for encryption
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> using HMAC_SHA1_96 for integrity
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> adding inbound ESP SA
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> SPI 0xc057ebc2, src 80.80.80.80 dst 90.90.90.90
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> adding outbound ESP SA
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> SPI 0x08d2fc52, src 90.90.90.90 dst 80.80.80.80
Mar 31 11:26:37 x.x.x.x charon: 06[IKE] <con-mobile|8> CHILD_SA con-mobile{5} established with SPIs c057ebc2_i 08d2fc52_o and TS 90.90.90.90/32|/0[udp/l2f] === 80.80.80.80/32|/0[udp/l2f]
Mar 31 11:26:37 x.x.x.x charon: 06[CHD] <con-mobile|8> CHILD_SA con-mobile{5} state change: INSTALLING => INSTALLED
Mar 31 11:26:38 x.x.x.x l2tps: Incoming L2TP packet from 80.80.80.80 1701
Mar 31 11:26:38 x.x.x.x l2tps: L2TP: Control connection 0x803252310 90.90.90.90 1701 <-> 80.80.80.80 1701 connected <=== Login form provided to client
Mar 31 11:26:38 x.x.x.x l2tps: L2TP: Incoming call #0 via connection 0x803252310 received
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] L2TP: Incoming call #0 via control connection 0x803252310 accepted
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] Link: OPEN event
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] LCP: Open event
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Initial --> Starting
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] LCP: LayerStart
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] L2TP: Call #0 connected
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] Link: UP event
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] LCP: Up event
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Starting --> Req-Sent
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #1
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:38 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #2
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:40 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #3
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:42 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #4
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:44 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #5
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:46 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #6
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:48 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #7
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:50 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #8
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:52 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #9
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:54 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #10
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x922f4812
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:26:56 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] LCP: parameter negotiation failed
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Req-Sent --> Stopped
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] LCP: LayerFinish
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] L2TP: Call #0 terminated locally
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] Link: DOWN event
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] LCP: Close event
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Stopped --> Closed
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] LCP: Down event
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Closed --> Initial
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] Link: SHUTDOWN event
Mar 31 11:26:59 x.x.x.x l2tps: [l2tp_l-1] Link: Shutdown
Mar 31 11:26:59 x.x.x.x l2tps: L2TP: Control connection 0x803252310 terminated: 0 ()
Mar 31 11:26:59 x.x.x.x charon: 09[NET] <con-mobile|8> received packet: from 80.80.80.80[44230] to 90.90.90.90[4500] (76 bytes)
Mar 31 11:26:59 x.x.x.x charon: 09[ENC] <con-mobile|8> parsed INFORMATIONAL_V1 request 2165796513 [ HASH D ]
Mar 31 11:26:59 x.x.x.x charon: 09[IKE] <con-mobile|8> received DELETE for ESP CHILD_SA with SPI 08d2fc52
Mar 31 11:26:59 x.x.x.x charon: 09[CHD] <con-mobile|8> CHILD_SA con-mobile{5} state change: INSTALLED => DELETING
Mar 31 11:26:59 x.x.x.x charon: 09[IKE] <con-mobile|8> closing CHILD_SA con-mobile{5} with SPIs c057ebc2_i (531 bytes) 08d2fc52_o (1680 bytes) and TS 90.90.90.90/32|/0[udp/l2f] === 80.80.80.80/32|/0[udp/l2f]
Mar 31 11:26:59 x.x.x.x charon: 09[CHD] <con-mobile|8> CHILD_SA con-mobile{5} state change: DELETING => DELETED
Mar 31 11:26:59 x.x.x.x charon: 09[CHD] <con-mobile|8> CHILD_SA con-mobile{5} state change: DELETED => DESTROYING
Mar 31 11:26:59 x.x.x.x charon: 05[NET] <con-mobile|8> received packet: from 80.80.80.80[44230] to 90.90.90.90[4500] (92 bytes)
Mar 31 11:26:59 x.x.x.x charon: 05[ENC] <con-mobile|8> parsed INFORMATIONAL_V1 request 3120117229 [ HASH D ]
Mar 31 11:26:59 x.x.x.x charon: 05[IKE] <con-mobile|8> received DELETE for IKE_SA con-mobile[8]
Mar 31 11:26:59 x.x.x.x charon: 05[IKE] <con-mobile|8> deleting IKE_SA con-mobile[8] between 90.90.90.90[90.90.90.90]...80.80.80.80[192.168.0.30]
Mar 31 11:26:59 x.x.x.x charon: 05[IKE] <con-mobile|8> IKE_SA con-mobile[8] state change: ESTABLISHED => DELETING
Mar 31 11:26:59 x.x.x.x charon: 05[IKE] <con-mobile|8> IKE_SA con-mobile[8] state change: DELETING => DELETING
Mar 31 11:26:59 x.x.x.x charon: 05[IKE] <con-mobile|8> IKE_SA con-mobile[8] state change: DELETING => DESTROYING <=== Client has not yet submited his credentials
BUT, if the user submits his credrentials within the 20 seconds time window, then LCP negociation terminates successfully, as shown in this log :
Mar 31 11:33:21 x.x.x.x charon: 05[NET] <9> received packet: from 80.80.80.80[34651] to 90.90.90.90[500] (408 bytes) <=== Client click on connect
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> parsed ID_PROT request 0 [ SA V V V V V V V V ]
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> looking for an IKEv1 config for 90.90.90.90...80.80.80.80
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> candidate: %any...%any, prio 24
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> candidate: %any...%any, prio 28
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> found matching ike config: %any...%any with prio 28
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> received unknown vendor ID: 01:52:8b:bb:c0:06:96:12:18:49:ab:9a:1c:5b:2a:51:00:00:00:01
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> received MS NT5 ISAKMPOAKLEY vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> received NAT-T (RFC 3947) vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> received FRAGMENTATION vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> received unknown vendor ID: fb:1d:e3:cd:f3:41:b7:ea:16:b7:e5:be:08:55:f1:20
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> received unknown vendor ID: 26:24:4d:38:ed:db:61:b3:17:2a:36:e3:d0:cf:b8:19
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> received unknown vendor ID: e3:a5:96:6a:76:37:9f:e7:07:22:82:31:e5:ce:86:52
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> 80.80.80.80 is initiating a Main Mode IKE_SA
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> IKE_SA (unnamed)[9] state change: CREATED => CONNECTING
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> selecting proposal:
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> no acceptable DIFFIE_HELLMAN_GROUP found
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> selecting proposal:
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> no acceptable ENCRYPTION_ALGORITHM found
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> selecting proposal:
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> proposal matches
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_384, IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/ECP_256, IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048, IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> selected proposal: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> sending XAuth vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> sending DPD vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> sending FRAGMENTATION vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> sending NAT-T (RFC 3947) vendor ID
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> generating ID_PROT response 0 [ SA V V V V ]
Mar 31 11:33:21 x.x.x.x charon: 05[NET] <9> sending packet: from 90.90.90.90[500] to 80.80.80.80[34651] (160 bytes)
Mar 31 11:33:21 x.x.x.x charon: 05[NET] <9> received packet: from 80.80.80.80[34651] to 90.90.90.90[500] (388 bytes)
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <9> remote host is behind NAT
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> candidate "bypasslan", match: 1/1/24 (me/other/ike)
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> candidate "con-mobile", match: 1/1/28 (me/other/ike)
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
Mar 31 11:33:21 x.x.x.x charon: 05[NET] <9> sending packet: from 90.90.90.90[500] to 80.80.80.80[34651] (372 bytes)
Mar 31 11:33:21 x.x.x.x charon: 05[NET] <9> received packet: from 80.80.80.80[41469] to 90.90.90.90[4500] (76 bytes)
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <9> parsed ID_PROT request 0 [ ID HASH ]
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> looking for pre-shared key peer configs matching 90.90.90.90...80.80.80.80[192.168.0.30]
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> candidate "bypasslan", match: 1/1/24 (me/other/ike)
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> candidate "con-mobile", match: 1/1/28 (me/other/ike)
Mar 31 11:33:21 x.x.x.x charon: 05[CFG] <9> selected peer config "con-mobile"
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <con-mobile|9> IKE_SA con-mobile[9] established between 90.90.90.90[90.90.90.90]...80.80.80.80[192.168.0.30]
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <con-mobile|9> IKE_SA con-mobile[9] state change: CONNECTING => ESTABLISHED
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <con-mobile|9> scheduling reauthentication in 28730s
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <con-mobile|9> maximum IKE_SA lifetime 28790s
Mar 31 11:33:21 x.x.x.x charon: 05[IKE] <con-mobile|9> DPD not supported by peer, disabled
Mar 31 11:33:21 x.x.x.x charon: 05[ENC] <con-mobile|9> generating ID_PROT response 0 [ ID HASH ]
Mar 31 11:33:21 x.x.x.x charon: 05[NET] <con-mobile|9> sending packet: from 90.90.90.90[4500] to 80.80.80.80[41469] (76 bytes)
Mar 31 11:33:21 x.x.x.x charon: 14[NET] <con-mobile|9> received packet: from 80.80.80.80[41469] to 90.90.90.90[4500] (444 bytes)
Mar 31 11:33:21 x.x.x.x charon: 14[ENC] <con-mobile|9> parsed QUICK_MODE request 1 [ HASH SA No ID ID NAT-OA NAT-OA ]
Mar 31 11:33:21 x.x.x.x charon: 14[IKE] <con-mobile|9> changing received traffic selectors 192.168.0.30/32|/0[udp/l2f]=== 90.90.90.90/32|/0[udp/l2f] due to NAT
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> looking for a child config for 90.90.90.90/32|/0[udp/l2f] === 80.80.80.80/32|/0[udp/l2f]
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> proposing traffic selectors for us:
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> 90.90.90.90/32|/0
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> proposing traffic selectors for other:
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> 80.80.80.80/32|/0
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> candidate "con-mobile" with prio 1+1
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> found matching child config "con-mobile" with prio 2
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> selecting traffic selectors for other:
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> config: 80.80.80.80/32|/0, received: 80.80.80.80/32|/0[udp/l2f] => match: 80.80.80.80/32|/0[udp/l2f]
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> selecting traffic selectors for us:
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> config: 90.90.90.90/32|/0, received: 90.90.90.90/32|/0[udp/l2f] => match: 90.90.90.90/32|/0[udp/l2f]
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> selecting proposal:
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> no acceptable ENCRYPTION_ALGORITHM found
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> selecting proposal:
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> proposal matches
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> received proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ, ESP:DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ, ESP:NULL/HMAC_SHA1_96/NO_EXT_SEQ
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> configured proposals: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
Mar 31 11:33:21 x.x.x.x charon: 14[CFG] <con-mobile|9> selected proposal: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
Mar 31 11:33:21 x.x.x.x charon: 14[IKE] <con-mobile|9> received 250000000 lifebytes, configured 0
Mar 31 11:33:21 x.x.x.x charon: 14[ENC] <con-mobile|9> generating QUICK_MODE response 1 [ HASH SA No ID ID NAT-OA NAT-OA ]
Mar 31 11:33:21 x.x.x.x charon: 14[NET] <con-mobile|9> sending packet: from 90.90.90.90[4500] to 80.80.80.80[41469] (204 bytes)
Mar 31 11:33:21 x.x.x.x charon: 14[NET] <con-mobile|9> received packet: from 80.80.80.80[41469] to 90.90.90.90[4500] (60 bytes)
Mar 31 11:33:21 x.x.x.x charon: 14[ENC] <con-mobile|9> parsed QUICK_MODE request 1 [ HASH ]
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> CHILD_SA con-mobile{6} state change: CREATED => INSTALLING
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> using AES_CBC for encryption
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> using HMAC_SHA1_96 for integrity
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> adding inbound ESP SA
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> SPI 0xcd0981aa, src 80.80.80.80 dst 90.90.90.90
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> adding outbound ESP SA
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> SPI 0x24ff7604, src 90.90.90.90 dst 80.80.80.80
Mar 31 11:33:21 x.x.x.x charon: 14[IKE] <con-mobile|9> CHILD_SA con-mobile{6} established with SPIs cd0981aa_i 24ff7604_o and TS 90.90.90.90/32|/0[udp/l2f] === 80.80.80.80/32|/0[udp/l2f]
Mar 31 11:33:21 x.x.x.x charon: 14[CHD] <con-mobile|9> CHILD_SA con-mobile{6} state change: INSTALLING => INSTALLED
Mar 31 11:33:22 x.x.x.x l2tps: Incoming L2TP packet from 80.80.80.80 1701
Mar 31 11:33:22 x.x.x.x l2tps: L2TP: Control connection 0x803252310 90.90.90.90 1701 <-> 80.80.80.80 1701 connected <=== Login form provided to client
Mar 31 11:33:22 x.x.x.x l2tps: L2TP: Incoming call #0 via connection 0x803252310 received
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] L2TP: Incoming call #0 via control connection 0x803252310 accepted
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] Link: OPEN event
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] LCP: Open event
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Initial --> Starting
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] LCP: LayerStart
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] L2TP: Call #0 connected
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] Link: UP event
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] LCP: Up event
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Starting --> Req-Sent
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #1
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x20f697a0
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:33:22 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #2
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x20f697a0
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:33:24 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #3
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x20f697a0
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:33:27 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #4
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x20f697a0
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:33:29 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] LCP: rec'd Configure Request #0 (Req-Sent)
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] MRU 1400
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x657119a2
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] CALLBACK 6
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigRej #0
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] CALLBACK 6
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] LCP: rec'd Configure Request #1 (Req-Sent)
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] MRU 1400
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x657119a2
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigAck #1
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] MRU 1400
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x657119a2
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:30 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Req-Sent --> Ack-Sent
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #5
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x20f697a0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: rec'd Configure Reject #5 (Ack-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MP MRRU 2048
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MP SHORTSEQ
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] ENDPOINTDISC [802.1] 00 50 56 95 f5 b6
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: SendConfigReq #6
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x20f697a0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: rec'd Configure Ack #6 (Ack-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] ACFCOMP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PROTOCOMP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MRU 1500
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MAGICNUM 0x20f697a0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] AUTHPROTO PAP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: state change Ack-Sent --> Opened <=== Client submits login form
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: auth: peer wants nothing, I want PAP
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: LayerUp
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: rec'd Ident #2 (Opened)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MESG: MSRASV5.20
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: rec'd Ident #3 (Opened)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] MESG: MSRAS-0-VMB018578
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: rec'd Ident #4 (Opened)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PAP: rec'd REQUEST #1 len: 29
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] AUTH: Trying RADIUS
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] RADIUS: Authenticating user 'username'
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] RADIUS: Rec'd RAD_ACCESS_ACCEPT for user 'username'
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] AUTH: RADIUS returned: authenticated
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PAP: Auth return status: authenticated
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PAP: Response is valid
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PAP: Reply message: privacyIDEA access granted
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] PAP: sending ACK #1 len: 31
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] LCP: authorization successful
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] Link: Matched action 'bundle "l2tp_b" ""'
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] Creating new bundle using template "l2tp_b".
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] Bundle: Interface ng0 created
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] Link: Join bundle "l2tp_b-1"
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: Open event
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: state change Initial --> Starting
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: LayerStart
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: Open event
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: state change Initial --> Starting
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: LayerStart
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: Up event
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: state change Starting --> Req-Sent
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: SendConfigReq #1
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: Up event
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: Protocol mppc disabled as useless for this setup
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: state change Starting --> Req-Sent
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: SendConfigReq #1
Mar 31 11:33:31 x.x.x.x charon: 14[KNL] interface ng0 appeared
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_l-1] rec'd unexpected protocol IPV6CP, rejecting
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Configure Request #6 (Req-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] MPPC
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] 0x01000001:MPPC, stateless
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: SendConfigRej #6
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] MPPC
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] 0x01000001:MPPC, stateless
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: rec'd Configure Request #7 (Req-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] NAKing with X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] PRIDNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] NAKing with X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] PRINBNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] SECDNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] NAKing with X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] SECNBNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: SendConfigRej #7
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] PRINBNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] SECNBNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: rec'd Configure Reject #1 (Req-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: SendConfigReq #2
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Configure Ack #1 (Req-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: state change Req-Sent --> Ack-Rcvd
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Terminate Request #8 (Ack-Rcvd)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: state change Ack-Rcvd --> Req-Sent
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] CCP: SendTerminateAck #2
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: rec'd Configure Request #9 (Req-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] NAKing with X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] PRIDNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] NAKing with X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] SECDNS 0.0.0.0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] NAKing with X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: SendConfigNak #9
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] PRIDNS X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] SECDNS X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: rec'd Configure Ack #2 (Req-Sent)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: state change Req-Sent --> Ack-Rcvd
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: rec'd Configure Request #10 (Ack-Rcvd)
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] X.X.X.X is OK
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] PRIDNS X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] SECDNS X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: SendConfigAck #10
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPADDR X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] PRIDNS X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] SECDNS X.X.X.X
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: state change Ack-Rcvd --> Opened
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IPCP: LayerUp
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] X.X.X.X -> X.X.X.X
Mar 31 11:33:31 x.x.x.x charon: 14[KNL] X.X.X.X appeared on ng0
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IFACE: No interface to proxy arp on for X.X.X.X
Mar 31 11:33:31 x.x.x.x charon: 14[KNL] fe80::250:56ff:fe95:f5b6 appeared on ng0
Mar 31 11:33:31 x.x.x.x root: login,l2tp,X.X.X.X,username
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IFACE: Up event
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IFACE: Rename interface ng0 to l2tp1
Mar 31 11:33:31 x.x.x.x kernel: ng0: changing name to 'l2tp1'
Mar 31 11:33:31 x.x.x.x charon: 09[KNL] interface ng0 disappeared
Mar 31 11:33:31 x.x.x.x l2tps: [l2tp_b-1] IFACE: Add group l2tp to ng0
Mar 31 11:33:33 x.x.x.x ntpd[43292]: Listen normally on 9 l2tp1 X.X.X.X:123
Mar 31 11:33:33 x.x.x.x ntpd[43292]: Listen normally on 10 l2tp1 [fe80::250:56ff:fe95:f5b6%7]:123
Mar 31 11:33:33 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Terminate Request #11 (Req-Sent)
Mar 31 11:33:33 x.x.x.x l2tps: [l2tp_b-1] CCP: SendTerminateAck #3
Mar 31 11:33:33 x.x.x.x l2tps: [l2tp_b-1] CCP: SendConfigReq #4
Mar 31 11:33:35 x.x.x.x l2tps: [l2tp_b-1] CCP: SendConfigReq #5
Mar 31 11:33:35 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Terminate Ack #5 (Req-Sent)
Mar 31 11:33:37 x.x.x.x l2tps: [l2tp_b-1] CCP: SendConfigReq #6
Mar 31 11:33:37 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Terminate Ack #6 (Req-Sent)
Mar 31 11:33:40 x.x.x.x l2tps: [l2tp_b-1] CCP: SendConfigReq #7
Mar 31 11:33:40 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Terminate Ack #7 (Req-Sent)
Mar 31 11:33:42 x.x.x.x l2tps: [l2tp_b-1] CCP: SendConfigReq #8
Mar 31 11:33:42 x.x.x.x l2tps: [l2tp_b-1] CCP: rec'd Terminate Ack #8 (Req-Sent)
Not sure if it is a bug, but is there a way to have LCP Config Request starts when credentials are submited ?
Or what could be a solution to work around this ?
The main goal here is to be able to have more than 20 seconds to submit credentials.
No data to display
Actions