pfSense English Support > IPsec

L2TP/IPsec windows client problems

(1/2) > >>

Cerberus:
Hello forum
 
It's time that I ask for your help. I have a netgate SG-2440 running pfsense 2.3.4-RELEASE.
 
It's configured for L2TP/IPsec. IPhone clients can connect fine, and traffic passes through the tunnel, no problem, but windows 7 & 10 clients cannot connect and get an error message "error 809". The exact same windows 7, 10 clients can connect without problems to a ubiquiti usg router configured for L2TP over IPsec.
 
Both the ubiquiti router and the pfsense router has a public IP address. The clients is connected to a phone hotspot.
 
In Status / IPsec / Overview on the PFsense box I can see the windows client is connected with success, but no traffic passes and disconnects after 35 seconds. I can see under "L2TP logins" that the windows clients never gets do an L2TP login, the IPhone does.
 
successful iphone connection
Jun 10 15:16:43   charon      14[KNL] 192.168.60.1 appeared on l2tp0
Jun 10 15:16:43   charon      15[KNL] interface l2tp0 activated
Jun 10 15:16:41   charon      15[IKE] <con1|53> CHILD_SA con1{119} established with SPIs c2cd7669_i 049d0e46_o and TS 92.xxx.xxx.59/32|/0[udp/l2f] === 92.xxx.xxx.55/32|/0[udp/49926]
Jun 10 15:16:41   charon      15[ENC] <con1|53> parsed QUICK_MODE request 474891996 [ HASH ]
Jun 10 15:16:41   charon      15[NET] <con1|53> received packet: from 92.xxx.xxx.55[4500] to 92.xxx.xxx.59[4500] (60 bytes)
Jun 10 15:16:41   charon      15[NET] <con1|53> sending packet: from 92.xxx.xxx.59[4500] to 92.xxx.xxx.55[4500] (196 bytes)
Jun 10 15:16:41   charon      15[ENC] <con1|53> generating QUICK_MODE response 474891996 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 10 15:16:41   charon      15[ENC] <con1|53> parsed QUICK_MODE request 474891996 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 10 15:16:41   charon      15[NET] <con1|53> received packet: from 92.xxx.xxx.55[4500] to 92.xxx.xxx.59[4500] (308 bytes)
Jun 10 15:16:40   charon      05[NET] <con1|53> sending packet: from 92.xxx.xxx.59[4500] to 92.xxx.xxx.55[4500] (68 bytes)
Jun 10 15:16:40   charon      05[ENC] <con1|53> generating ID_PROT response 0 [ ID HASH ]
Jun 10 15:16:40   charon      05[IKE] <con1|53> maximum IKE_SA lifetime 28444s
Jun 10 15:16:40   charon      05[IKE] <con1|53> scheduling reauthentication in 27904s
Jun 10 15:16:40   charon      05[IKE] <con1|53> IKE_SA con1[53] established between 92.xxx.xxx.59[92.xxx.xxx.59]...92.xxx.xxx.55[10.0.1.203]
Jun 10 15:16:40   charon      05[CFG] <53> selected peer config "con1"
Jun 10 15:16:40   charon      05[CFG] <53> looking for pre-shared key peer configs matching 92.xxx.xxx.59...92.xxx.xxx.55[10.0.1.203]
Jun 10 15:16:40   charon      05[ENC] <53> parsed ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ]
Jun 10 15:16:40   charon      05[NET] <53> received packet: from 92.xxx.xxx.55[4500] to 92.xxx.xxx.59[4500] (100 bytes)
Jun 10 15:16:40   charon      05[NET] <53> sending packet: from 92.xxx.xxx.59[500] to 92.xxx.xxx.55[500] (244 bytes)
Jun 10 15:16:40   charon      05[ENC] <53> generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
Jun 10 15:16:40   charon      05[IKE] <53> remote host is behind NAT
Jun 10 15:16:40   charon      05[ENC] <53> parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
Jun 10 15:16:40   charon      05[NET] <53> received packet: from 92.xxx.xxx.55[500] to 92.xxx.xxx.59[500] (228 bytes)
Jun 10 15:16:40   charon      05[NET] <53> sending packet: from 92.xxx.xxx.59[500] to 92.xxx.xxx.55[500] (156 bytes)
Jun 10 15:16:40   charon      05[ENC] <53> generating ID_PROT response 0 [ SA V V V V ]
Jun 10 15:16:40   charon      05[IKE] <53> 92.xxx.xxx.55 is initiating a Main Mode IKE_SA
Jun 10 15:16:40   charon      05[IKE] <53> received DPD vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received FRAGMENTATION vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-02 vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-03 vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-04 vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-05 vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-06 vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-07 vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike-08 vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received draft-ietf-ipsec-nat-t-ike vendor ID
Jun 10 15:16:40   charon      05[IKE] <53> received NAT-T (RFC 3947) vendor ID
Jun 10 15:16:40   charon      05[ENC] <53> parsed ID_PROT request 0 [ SA V V V V V V V V V V V V ]
Jun 10 15:16:39   charon      05[NET] <53> received packet: from 92.xxx.xxx.55[500] to 92.xxx.xxx.59[500] (788 bytes)
 
-------------------------------------------------------------------
unsuccessful windows 10 connection attempt.
Jun 10 15:27:55   charon      10[IKE] <con1|58> closing CHILD_SA con1{142} with SPIs c4c238e9_i (0 bytes) 4c737218_o (0 bytes) and TS 92.xxx.xxx.59/32|/0[udp/l2f] === 92.xxx.202.132/32|/0[udp/l2f]
Jun 10 15:27:55   charon      10[IKE] <con1|58> received DELETE for ESP CHILD_SA with SPI 4c737218
Jun 10 15:27:55   charon      10[ENC] <con1|58> parsed INFORMATIONAL_V1 request 1604456146 [ HASH D ]
Jun 10 15:27:55   charon      10[NET] <con1|58> received packet: from 92.xxx.202.132[4500] to 92.xxx.xxx.59[4500] (76 bytes)
Jun 10 15:27:55   charon      06[IKE] <con1|58> CHILD_SA con1{143} established with SPIs c6329692_i f110b87e_o and TS 92.xxx.xxx.59/32|/0[udp/l2f] === 92.xxx.202.132/32|/0[udp/l2f]
Jun 10 15:27:55   charon      06[ENC] <con1|58> parsed QUICK_MODE request 2 [ HASH ]
Jun 10 15:27:55   charon      06[NET] <con1|58> received packet: from 92.xxx.202.132[4500] to 92.xxx.xxx.59[4500] (60 bytes)
Jun 10 15:27:55   charon      06[NET] <con1|58> sending packet: from 92.xxx.xxx.59[4500] to 92.xxx.202.132[4500] (204 bytes)
Jun 10 15:27:55   charon      06[ENC] <con1|58> generating QUICK_MODE response 2 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 10 15:27:55   charon      06[IKE] <con1|58> detected rekeying of CHILD_SA con1{142}
Jun 10 15:27:55   charon      06[IKE] <con1|58> received 250000000 lifebytes, configured 0
Jun 10 15:27:55   charon      06[ENC] <con1|58> parsed QUICK_MODE request 2 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 10 15:27:55   charon      06[NET] <con1|58> received packet: from 92.xxx.202.132[4500] to 92.xxx.xxx.59[4500] (332 bytes)
Jun 10 15:27:55   charon      06[IKE] <con1|58> CHILD_SA con1{142} established with SPIs c4c238e9_i 4c737218_o and TS 92.xxx.xxx.59/32|/0[udp/l2f] === 92.xxx.202.132/32|/0[udp/l2f]
Jun 10 15:27:55   charon      06[ENC] <con1|58> parsed QUICK_MODE request 1 [ HASH ]
Jun 10 15:27:55   charon      06[NET] <con1|58> received packet: from 92.xxx.202.132[4500] to 92.xxx.xxx.59[4500] (60 bytes)
Jun 10 15:27:55   charon      06[NET] <con1|58> sending packet: from 92.xxx.xxx.59[4500] to 92.xxx.202.132[4500] (204 bytes)
Jun 10 15:27:55   charon      06[ENC] <con1|58> generating QUICK_MODE response 1 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 10 15:27:55   charon      06[IKE] <con1|58> received 250000000 lifebytes, configured 0
Jun 10 15:27:55   charon      06[ENC] <con1|58> parsed QUICK_MODE request 1 [ HASH SA No ID ID NAT-OA NAT-OA ]
Jun 10 15:27:55   charon      06[NET] <con1|58> received packet: from 92.xxx.202.132[4500] to 92.xxx.xxx.59[4500] (332 bytes)
Jun 10 15:27:55   charon      11[NET] <con1|58> sending packet: from 92.xxx.xxx.59[4500] to 92.xxx.202.132[4500] (68 bytes)
Jun 10 15:27:55   charon      11[ENC] <con1|58> generating ID_PROT response 0 [ ID HASH ]
Jun 10 15:27:55   charon      11[IKE] <con1|58> DPD not supported by peer, disabled
Jun 10 15:27:55   charon      11[IKE] <con1|58> maximum IKE_SA lifetime 28330s
Jun 10 15:27:55   charon      11[IKE] <con1|58> scheduling reauthentication in 27790s
Jun 10 15:27:55   charon      11[IKE] <con1|58> IKE_SA con1[58] established between 92.xxx.xxx.59[92.xxx.xxx.59]...92.xxx.202.132[172.16.0.150]
Jun 10 15:27:55   charon      11[CFG] <58> selected peer config "con1"
Jun 10 15:27:55   charon      11[CFG] <58> looking for pre-shared key peer configs matching 92.xxx.xxx.59...92.xxx.202.132[172.16.0.150]
Jun 10 15:27:55   charon      11[ENC] <58> parsed ID_PROT request 0 [ ID HASH ]
Jun 10 15:27:55   charon      11[NET] <58> received packet: from 92.xxx.202.132[4500] to 92.xxx.xxx.59[4500] (68 bytes)
Jun 10 15:27:55   charon      11[NET] <58> sending packet: from 92.xxx.xxx.59[500] to 92.xxx.202.132[500] (244 bytes)
Jun 10 15:27:55   charon      11[ENC] <58> generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
Jun 10 15:27:55   charon      11[IKE] <58> remote host is behind NAT
Jun 10 15:27:55   charon      11[ENC] <58> parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
Jun 10 15:27:55   charon      11[NET] <58> received packet: from 92.xxx.202.132[500] to 92.xxx.xxx.59[500] (260 bytes)
Jun 10 15:27:55   charon      11[NET] <58> sending packet: from 92.xxx.xxx.59[500] to 92.xxx.202.132[500] (156 bytes)
Jun 10 15:27:55   charon      11[ENC] <58> generating ID_PROT response 0 [ SA V V V V ]
Jun 10 15:27:55   charon      11[IKE] <58> 92.xxx.202.132 is initiating a Main Mode IKE_SA
Jun 10 15:27:55   charon      11[ENC] <58> received unknown vendor ID: e3:a5:96:6a:76:37:9f:e7:07:22:82:31:e5:ce:86:52
Jun 10 15:27:55   charon      11[ENC] <58> received unknown vendor ID: 26:24:4d:38:ed:db:61:b3:17:2a:36:e3:d0:cf:b8:19
Jun 10 15:27:55   charon      11[ENC] <58> received unknown vendor ID: fb:1d:e3:cd:f3:41:b7:ea:16:b7:e5:be:08:55:f1:20
Jun 10 15:27:55   charon      11[IKE] <58> received FRAGMENTATION vendor ID
Jun 10 15:27:55   charon      11[IKE] <58> received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Jun 10 15:27:55   charon      11[IKE] <58> received NAT-T (RFC 3947) vendor ID
Jun 10 15:27:55   charon      11[IKE] <58> received MS NT5 ISAKMPOAKLEY vendor ID
Jun 10 15:27:55   charon      11[ENC] <58> received unknown vendor ID: 01:52:8b:bb:c0:06:96:12:18:49:ab:9a:1c:5b:2a:51:00:00:00:01
Jun 10 15:27:55   charon      11[ENC] <58> parsed ID_PROT request 0 [ SA V V V V V V V V ]
Jun 10 15:27:55   charon      11[NET] <58> received packet: from 92.xxx.202.132[500] to 92.xxx.xxx.59[500] (408 bytes)
 
 
The reg fix, does not fix this.
[HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\services\PolicyAgent]
"AssumeUDPEncapsulationContextOnSendRule"=dword:00000002
 

Cerberus:
I just found out, that if I place the windows 10 client behinde the pfsense box, it can create the L2TP/IPsec connection. What am I missing here ?

Cerberus:
Update: If the windows 10 client has a public IP address it works!
 
This makes me believe it's a NAT problem. There must be a configuration error on the pfsense router, the win10 client and the pfsense router, does not agree on how NAT-T works.
 
Remember the same windows 10 client can successfully connect to another router via L2TP/IPsec when the client is behind nat.

Cerberus:
Update:

OSX Sierra (10.12) clients connect without any issues, also from behind nat.

Protech:
I am having the exact same problem.  L2TP server setup directly on the pfSense.  Mobile clients can connect and Windows clients can connect from inside the network, but the tunnel times out when you try to connect from outside the network.  I have setup 100s of L2TP VPN's both hosted on routers and also passthrough and I have never had this much trouble.  I have a team of engineers here and we are all stumped.  It is definitely so broken or weird setting on the pfSense.  When a windows client tries to connect it starts the handshake, but then both clients state that the other one stopped responding.  I have followed every article I can find and no solutions.  I also have checked the firewall rules and traffic just stops as soon as the client starts negotiations.  A client bought this firewall and it's extremely frustrating compared to a Meraki on which I can setup a L2TP VPN with AD integration in less than 15 minutes without any issues.

I have spent about 6 hours troubleshooting this and 2 other engineers have spent another 6 hours.

PLEASE help!!

I also noticed that the NTP logs state that it's using L2TP to update.  The times match the L2TP logs exactly.

I checked the firewall rule for IPsec and when a client tries to connect it just sits in state "NO_TRAFFIC:SINGLE"  any only transmits a few packets one way.
IPsec    udp    216.196.231.50:1701 -> 24.123.6.70:1701    NO_TRAFFIC:SINGLE    5 / 0    745 B / 0 B

Here is the NTP log:
Jun 23 18:15:22    ntpd    20270    Deleting interface #48 l2tp0, 192.168.1.252#123, interface stats: received=0, sent=0, dropped=0, active_time=4 secs
Jun 23 18:15:18    ntpd    20270    Listen normally on 48 l2tp0 192.168.1.252:123


Here is the L2TP service log:
Jun 23 18:15:31    l2tps       L2TP: Control connection 0x80301b608 destroyed
Jun 23 18:15:20    l2tps       [l2tp0] LCP: Close event
Jun 23 18:15:20    l2tps       [l2tp0] link: CLOSE event
Jun 23 18:15:20    l2tps       L2TP: Control connection 0x80301b608 terminated: 0 ()
Jun 23 18:15:20    l2tps       [l2tp0] LCP: state change Closing --> Initial
Jun 23 18:15:20    l2tps       [l2tp0] LCP: LayerFinish
Jun 23 18:15:20    l2tps       [l2tp0] LCP: Down event
Jun 23 18:15:20    l2tps       [l2tp0] LCP: state change Stopping --> Closing
Jun 23 18:15:20    l2tps       [l2tp0] LCP: Close event
Jun 23 18:15:20    l2tps       [l2tp0] link: DOWN event
Jun 23 18:15:20    l2tps       [l2tp0] L2TP: call #14 terminated: result=2 error=6 errmsg="control connection closing"
Jun 23 18:15:20    l2tps       [l2tp0] LCP: LayerDown
Jun 23 18:15:20    l2tps       [l2tp0] LCP: SendTerminateAck #8
Jun 23 18:15:20    l2tps       [l2tp0] AUTH: Cleanup
Jun 23 18:15:20    l2tps       [l2tp0] CCP: state change Closed --> Initial
Jun 23 18:15:20    l2tps       [l2tp0] CCP: Down event
Jun 23 18:15:20    l2tps       [l2tp0] IPCP: state change Closing --> Initial
Jun 23 18:15:20    l2tps       [l2tp0] closing link "l2tp0"...
Jun 23 18:15:20    l2tps       [l2tp0] No NCPs left. Closing links...
Jun 23 18:15:20    l2tps       [l2tp0] IPCP: LayerFinish
Jun 23 18:15:20    l2tps       [l2tp0] IPCP: Down event
Jun 23 18:15:20    l2tps       [l2tp0] CCP: state change Stopped --> Closed
Jun 23 18:15:20    l2tps       [l2tp0] CCP: Close event
Jun 23 18:15:20    l2tps       [l2tp0] IFACE: Down event
Jun 23 18:15:20    l2tps       [l2tp0] IPCP: LayerDown
Jun 23 18:15:20    l2tps       [l2tp0] error writing len 8 frame to bypass: Network is down
Jun 23 18:15:20    l2tps       [l2tp0] IPCP: SendTerminateReq #12
Jun 23 18:15:20    l2tps       [l2tp0] IPCP: state change Opened --> Closing
Jun 23 18:15:20    l2tps       [l2tp0] IPCP: Close event
Jun 23 18:15:20    l2tps       [l2tp0] Bundle up: 0 links, total bandwidth 9600 bps
Jun 23 18:15:20    l2tps       [l2tp0] AUTH: Accounting data for user testadmin: 4 seconds, 5211 octets in, 16394 octets out
Jun 23 18:15:20    l2tps       [l2tp0] LCP: state change Opened --> Stopping


Here is the IPsec log:
Jun 23 19:26:36    charon       08[MGR] checkin and destroy of IKE_SA successful
Jun 23 19:26:36    charon       08[MGR] checkin and destroy of IKE_SA successful
Jun 23 19:26:36    charon       08[IKE] <con1|23> IKE_SA con1[23] state change: DELETING => DESTROYING
Jun 23 19:26:36    charon       08[IKE] IKE_SA con1[23] state change: DELETING => DESTROYING
Jun 23 19:26:36    charon       08[MGR] <con1|23> checkin and destroy IKE_SA con1[23]
Jun 23 19:26:36    charon       08[MGR] checkin and destroy IKE_SA con1[23]
Jun 23 19:26:36    charon       08[IKE] <con1|23> IKE_SA con1[23] state change: DELETING => DELETING
Jun 23 19:26:36    charon       08[IKE] IKE_SA con1[23] state change: DELETING => DELETING
Jun 23 19:26:36    charon       08[IKE] <con1|23> IKE_SA con1[23] state change: ESTABLISHED => DELETING
Jun 23 19:26:36    charon       08[IKE] IKE_SA con1[23] state change: ESTABLISHED => DELETING
Jun 23 19:26:36    charon       08[IKE] <con1|23> deleting IKE_SA con1[23] between 24.123.6.70[24.123.6.70]...216.196.231.50[192.168.179.180]
Jun 23 19:26:36    charon       08[IKE] deleting IKE_SA con1[23] between 24.123.6.70[24.123.6.70]...216.196.231.50[192.168.179.180]
Jun 23 19:26:36    charon       08[IKE] <con1|23> received DELETE for IKE_SA con1[23]
Jun 23 19:26:36    charon       08[IKE] received DELETE for IKE_SA con1[23]
Jun 23 19:26:36    charon       08[IKE] <con1|23> 16: 15 BF C3 15 ....
Jun 23 19:26:36    charon       08[IKE] <con1|23> 0: A2 B8 F2 F3 EE 29 46 42 12 83 F3 09 AD 90 1B D6 .....)FB........
Jun 23 19:26:36    charon       08[IKE] <con1|23> Hash => 20 bytes @ 0x80d134460
Jun 23 19:26:36    charon       08[IKE] 16: 15 BF C3 15 ....
Jun 23 19:26:36    charon       08[IKE] 0: A2 B8 F2 F3 EE 29 46 42 12 83 F3 09 AD 90 1B D6 .....)FB........
Jun 23 19:26:36    charon       08[IKE] Hash => 20 bytes @ 0x80d134460
Jun 23 19:26:36    charon       08[ENC] <con1|23> parsed INFORMATIONAL_V1 request 332373922 [ HASH D ]
Jun 23 19:26:36    charon       08[IKE] <con1|23> 0: 2C 6B F0 62 50 FA BD E1 9A 73 84 86 14 F8 A7 6E ,k.bP....s.....n
Jun 23 19:26:36    charon       08[IKE] <con1|23> next IV for MID 332373922 => 16 bytes @ 0x80d134840
Jun 23 19:26:36    charon       08[IKE] 0: 2C 6B F0 62 50 FA BD E1 9A 73 84 86 14 F8 A7 6E ,k.bP....s.....n
Jun 23 19:26:36    charon       08[IKE] next IV for MID 332373922 => 16 bytes @ 0x80d134840
Jun 23 19:26:36    charon       08[NET] <con1|23> received packet: from 216.196.231.50[4500] to 24.123.6.70[4500] (92 bytes)
Jun 23 19:26:36    charon       08[MGR] IKE_SA con1[23] successfully checked out
Jun 23 19:26:36    charon       08[MGR] IKE_SA con1[23] successfully checked out
Jun 23 19:26:36    charon       09[MGR] <con1|23> checkin of IKE_SA successful
Jun 23 19:26:36    charon       09[MGR] checkin of IKE_SA successful
Jun 23 19:26:36    charon       09[MGR] <con1|23> checkin IKE_SA con1[23]
Jun 23 19:26:36    charon       09[MGR] checkin IKE_SA con1[23]


Navigation

[0] Message Index

[#] Next page

Go to full version