Ipsec L2L unstable

mik256

USG Flex 50 (latest firmware) behind NAT as initiator, stronswan on the other side of the tunnel (also behind NAT, with 500 and 4500 ports redirected).

Tunnel is working fine, but I got random disconnects after several hours sometimes even a day or two, it disconnects and only way how to bring the tunnel back is to reboot zyxel. Then after reboot, it gets instantly connected. There are lot of other tunnels setup on strongswan, mostly tplinks without any issues.

In logs, I can see the following:

Zyxel

[INIT] Send:[SAi1][KE][NONCE][NOTIFY][NOTIFY][VID][VID][VID][VID][VID] 192.168.255.6:500 strongswanPublicIP:500
[INIT] Recv:[SA][KE][NONCE][NOTIFY][NOTIFY][CERTREQ][NOTIFY] strongswanPublicIP:500 192.168.255.6:500
[AUTH] Send:[IDi][CERTREQ][IDr][AUTH][SAi2][TSi][TSr][NOTIFY][NOTIFY][NOTIFY][NOTIFY] 192.168.255.6:4500 strongswanPublicIP:4500
The cookie pair is : 0x664c01cb0705eeef / 0x055c76de34c4e750 192.168.255.6:4500 strongswanPublicIP:4500
IKE SA [mVPN] is disconnected 192.168.255.6:4500 strongswanPublicIP:4500

StrongSwan

received packet: from zyxelPublicIP[55905] to strongswanNATip[500] (648 bytes)
parsed IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) V V V V V ]
zyxelPublicIP is initiating an IKE_SA
generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(MULT_AUTH) ]
sending packet: from 192.168.40.2[500] to zyxelPublicIP[55905] (505 bytes)

What can I do to make the tunnel stable?

Zyxel_James

the logs seem not complete, could you help collect the logs on both sides in three different scenarios? I would like to check the difference in the behavior.

1. The complete log of strongswan connect to VPN successfully
2. The complete log of strongswan disconnect after connecting successfully
3. The complete log of strongswan fails to connect to VPN.

mik256

Hello, there are many working tunnels on strongswan side, so it's a bit hard do distinguish what belongs to the problematic zyxel one. However, I was able to dig these from unsuccessful reconnection attempt. Strangely, I can't see the Send:[ID][HASH][NOTIFY:INITIAL_CONTACT] 192.168.255.6:4500 strongSwanPublicIP:4500 in strongswan tcpdump and also after zyxel reboot, everything starts working again.

zyxel
2 11.04.2024 9:36 info IKE ISAKMP SA [mKerioIKEv1] is disconnected 192.168.255.6:4500 strongSwanPublicIP:4500 IKE_LOG
3 11.04.2024 9:36 info IKE The cookie pair is : 0x13e9ecf79ca29e16 / 0x7d63139f1706965c 192.168.255.6:4500 strongSwanPublicIP:4500 IKE_LOG
4 11.04.2024 9:35 info IKE Send:[ID][HASH][NOTIFY:INITIAL_CONTACT] 192.168.255.6:4500 strongSwanPublicIP:4500 IKE_LOG
5 11.04.2024 9:35 info IKE The cookie pair is : 0x13e9ecf79ca29e16 / 0x7d63139f1706965c 192.168.255.6:4500 strongSwanPublicIP:4500 IKE_LOG
6 11.04.2024 9:35 info IKE Recv:[KE][NONCE][PRV][PRV] strongSwanPublicIP:500 192.168.255.6:500 IKE_LOG
7 11.04.2024 9:35 info IKE Send:[KE][NONCE][PRV][PRV] 192.168.255.6:500 strongSwanPublicIP:500 IKE_LOG
8 11.04.2024 9:35 info IKE The cookie pair is : 0x13e9ecf79ca29e16 / 0x7d63139f1706965c 192.168.255.6:500 strongSwanPublicIP:500 IKE_LOG
9 11.04.2024 9:35 info IKE Recv:[SA][VID][VID][VID] strongSwanPublicIP:500 192.168.255.6:500 IKE_LOG
10 11.04.2024 9:35 info IKE The cookie pair is : 0x7d63139f1706965c / 0x13e9ecf79ca29e16 [count=2] strongSwanPublicIP:500 192.168.255.6:500 IKE_LOG
11 11.04.2024 9:35 info IKE Send:[SA][VID][VID][VID][VID][VID][VID][VID][VID][VID][VID] 192.168.255.6:500 strongSwanPublicIP:500 IKE_LOG
12 11.04.2024 9:35 info IKE Send Main Mode request to [212.20.119.106] 192.168.255.6:500 strongSwanPublicIP:500 IKE_LOG
13 11.04.2024 9:35 info IKE Tunnel [mKerioVPN] Sending IKE request 192.168.255.6:500 strongSwanPublicIP:500 IKE_LOG
14 11.04.2024 9:35 info IKE The cookie pair is : 0x13e9ecf79ca29e16 / 0x0000000000000000 [count=3] 192.168.255.6:500 strongSwanPublicIP:500 IKE_LOG

strongswan
[11/Apr/2024 10:20:27] {charon} charon: 08[NET] received packet: from zyxelPublicIP[56228] to 192.168.40.2[500] (398 bytes)
[11/Apr/2024 10:20:27] {charon} charon: 08[ENC] parsed ID_PROT request 0 [ SA V V V V V V V V V V ]
[11/Apr/2024 10:20:27] {charon} charon: 08[ENC] received unknown vendor ID: f7:58:f2:26:68:75:0f:03:b0:8d:f6:eb:e1:d0:04:03
[11/Apr/2024 10:20:27] {charon} charon: 08[IKE] received draft-ietf-ipsec-nat-t-ike-02 vendor ID
[11/Apr/2024 10:20:27] {charon} charon: 08[IKE] received draft-ietf-ipsec-nat-t-ike-02\n vendor ID
[11/Apr/2024 10:20:27] {charon} charon: 08[IKE] received draft-ietf-ipsec-nat-t-ike-03 vendor ID
[11/Apr/2024 10:20:27] {charon} charon: 08[IKE] received NAT-T (RFC 3947) vendor ID
[11/Apr/2024 10:20:27] {charon} charon: 08[IKE] received DPD vendor ID
[11/Apr/2024 10:20:27] {charon} charon: 08[ENC] received unknown vendor ID: af:ca:d7:13:68:a1:f1:c9:6b:86:96:fc:77:57
[11/Apr/2024 10:20:27] {charon} charon: 08[ENC] received unknown vendor ID: f9:19:6d:f8:6b:81:2f:b0:f6:80:26:d8:87:6d:cb:7b:00:04:32:00
[11/Apr/2024 10:20:27] {charon} charon: 08[ENC] received unknown vendor ID: ac:40:f8:c4:38:99:27:c6:e8:ac:24:53:1b:b7:8b:2b:3f:44:3b:a4:f0:23:38:3c:49:1a:36:9a:08:84:3a:5d:f9:86:fc:5c:c1:4b:ae:ed:8c:ec:b7:90:8f:24:1f:e6:3c:a8:1d:4b:5b:70:72:48:33:6a:19:a8:ae:40:68:99:48:18:f0:de:8a:85:a5:c9:82:f4:e6:6c:12:32:0f:62:9b:74:3d:c1:e7:56:f3:35:5d:9c:a5:b8:b9:e5:67:df:8f:4c:71:15:77:11:75:3d:04:ba:91:e3:65:c1:7d:da:76:82:d4:45:5a:3f:fc:63:2e:57:10:55:91:8e:4e:15
[11/Apr/2024 10:20:27] {charon} charon: 08[ENC] received unknown vendor ID: b6:c9:8c:ca:29:0a:eb:be:37:f1:9f:31:12:d2:d7:cb
[11/Apr/2024 10:20:27] {charon} charon: 08[IKE] zyxelPublicIP is initiating a Main Mode IKE_SA
[11/Apr/2024 10:20:27] {charon} charon: 08[ENC] generating ID_PROT response 0 [ SA V V V ]
[11/Apr/2024 10:20:27] {charon} charon: 08[NET] sending packet: from 192.168.40.2[500] to zyxelPublicIP[56228] (136 bytes)
[11/Apr/2024 10:20:28] {charon} charon: 12[NET] received packet: from zyxelPublicIP[56228] to 192.168.40.2[500] (356 bytes)
[11/Apr/2024 10:20:28] {charon} charon: 12[ENC] parsed ID_PROT request 0 [ KE No NAT-D NAT-D ]
[11/Apr/2024 10:20:28] {charon} charon: 12[IKE] local host is behind NAT, sending keep alives
[11/Apr/2024 10:20:28] {charon} charon: 12[IKE] remote host is behind NAT
[11/Apr/2024 10:20:28] {charon} charon: 12[IKE] trying shared key for '%any'[(null)] - '%any'[(null)]
[11/Apr/2024 10:20:28] {charon} charon: 12[ENC] generating ID_PROT response 0 [ KE No NAT-D NAT-D ]
[11/Apr/2024 10:20:28] {charon} charon: 12[NET] sending packet: from 192.168.40.2[500] to zyxelPublicIP[56228] (372 bytes)

mik256

And after reboot, the tunnel connects instantly again:

63 11.04.2024 10:26 info IKE Tunnel [mKerioIKEv1:mKerioVPN:0xc77fb2c7] built successfully 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
64 11.04.2024 10:26 info IKE [ESP aes-cbc|hmac-sha1-96][SPI 0x8cdfb2f6|0xc77fb2c7][Lifetime 3180] 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
65 11.04.2024 10:26 info IKE [Policy: ipv4(192.168.29.0-192.168.29.255)-ipv4(10.0.0.0-10.255.255.255)] 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
66 11.04.2024 10:26 info IKE [Initiator:192.168.255.6][Responder:StrongSwanPublicIP] 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
67 11.04.2024 10:26 info IKE Send:[HASH] 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
68 11.04.2024 10:26 info IKE Recv:[HASH][SA][NONCE][ID][ID]  StrongSwanPublicIP:4500 192.168.255.6:4500 IKE_LOG
69 11.04.2024 10:26 info IKE Send:[HASH][SA][NONCE][ID][ID] 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
70 11.04.2024 10:26 info IKE Phase 1 IKE SA process done 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
71 11.04.2024 10:26 info IKE Recv:[ID][HASH]  StrongSwanPublicIP:4500 192.168.255.6:4500 IKE_LOG
72 11.04.2024 10:26 info IKE The cookie pair is : 0x5f830de2927846be / 0x1fc01b707673badb [count=2]  StrongSwanPublicIP:4500 192.168.255.6:4500 IKE_LOG
73 11.04.2024 10:26 info IKE Send:[ID][HASH][NOTIFY:INITIAL_CONTACT] 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
74 11.04.2024 10:26 info IKE The cookie pair is : 0x1fc01b707673badb / 0x5f830de2927846be [count=8] 192.168.255.6:4500  StrongSwanPublicIP:4500 IKE_LOG
75 11.04.2024 10:26 info System NTP update has succeeded. Current time is Thu Apr 11 10:26:38 UTC +02:00 DST 2024. Last time is Thu Apr 11 10:26:09 UTC +02:00 DST 2024. System
76 11.04.2024 10:26 info IKE Recv:[KE][NONCE][PRV][PRV]  StrongSwanPublicIP:500 192.168.255.6:500 IKE_LOG
77 11.04.2024 10:26 info IKE Send:[KE][NONCE][PRV][PRV] 192.168.255.6:500  StrongSwanPublicIP:500 IKE_LOG
78 11.04.2024 10:26 info IKE The cookie pair is : 0x1fc01b707673badb / 0x5f830de2927846be 192.168.255.6:500  StrongSwanPublicIP:500 IKE_LOG
79 11.04.2024 10:26 info Policy Route Trunk SYSTEM_DEFAULT_WAN_TRUNK alive, related policy route rules will be re-enabled. TRUNK ALIVE
80 11.04.2024 10:26 info Policy Route Interface wan alive, related policy route rules will be re-enabled. INTERFACE ALIVE
81 11.04.2024 10:26 alert System Device starts up.
82 11.04.2024 10:26 info IKE Recv:[SA][VID][VID][VID]  StrongSwanPublicIP:500 192.168.255.6:500 IKE_LOG
83 11.04.2024 10:26 info IKE The cookie pair is : 0x5f830de2927846be / 0x1fc01b707673badb [count=2]  StrongSwanPublicIP:500 192.168.255.6:500 IKE_LOG
84 11.04.2024 10:26 info IKE Send:[SA][VID][VID][VID][VID][VID][VID][VID][VID][VID][VID] 192.168.255.6:500  StrongSwanPublicIP:500 IKE_LOG
85 11.04.2024 10:26 info IKE Send Main Mode request to [StrongSwanPublicIP] 192.168.255.6:500  StrongSwanPublicIP:500 IKE_LOG
86 11.04.2024 10:26 info IKE Tunnel [mKerioVPN] Sending IKE request 192.168.255.6:500  StrongSwanPublicIP:500 IKE_LOG
87 11.04.2024 10:26 info IKE The cookie pair is : 0x1fc01b707673badb / 0x0000000000000000 [count=3] 192.168.255.6:500  StrongSwanPublicIP:500 IKE_LOG

[11/Apr/2024 10:26:40] {charon} charon: 07[NET] received packet: from zyxelPublicIP[56107] to 192.168.40.2[4500] (92 bytes)
[11/Apr/2024 10:26:40] {charon} charon: 07[IKE] trying shared key for 'StrongSwanPublicIP'[(null)] - '195.12.150.178'[(null)]
[11/Apr/2024 10:26:40] {charon} charon: 07[ENC] parsed ID_PROT request 0 [ ID HASH N(INITIAL_CONTACT) ]
[11/Apr/2024 10:26:40] {charon} charon: 07[CFG] looking for pre-shared key peer configs matching 192.168.40.2...zyxelPublicIP[192.168.255.6]
[11/Apr/2024 10:26:40] {charon} charon: 07[CFG] Including peer config "tunnel_13_1_1_1"
[11/Apr/2024 10:26:40] {charon} charon: 07[CFG] Skipping peer config "vpnserver_1" - PSK mismatch
[11/Apr/2024 10:26:40] {charon} charon: 07[CFG] selected peer config "tunnel_13_1_1_1"
[11/Apr/2024 10:26:40] {charon} charon: 07[IKE] IKE_SA tunnel_13_1_1_1[6302] established between 192.168.40.2[StrongSwanPublicIP]...zyxelPublicIP[192.168.255.6]
[11/Apr/2024 10:26:40] {charon} charon: 07[ENC] generating ID_PROT response 0 [ ID HASH ]
[11/Apr/2024 10:26:40] {charon} charon: 07[NET] sending packet: from 192.168.40.2[4500] to zyxelPublicIP[56107] (76 bytes)
[11/Apr/2024 10:26:41] {charon} charon: 08[NET] received packet: from zyxelPublicIP[56107] to 192.168.40.2[4500] (156 bytes)
[11/Apr/2024 10:26:41] {charon} charon: 08[ENC] parsed QUICK_MODE request 2407479896 [ HASH SA No ID ID ]
[11/Apr/2024 10:26:41] {charon} charon: 08[IKE] received 3600s lifetime, configured 0s
[11/Apr/2024 10:26:41] {charon} charon: 08[ENC] generating QUICK_MODE response 2407479896 [ HASH SA No ID ID ]
[11/Apr/2024 10:26:41] {charon} charon: 08[NET] sending packet: from 192.168.40.2[4500] to zyxelPublicIP[56107] (188 bytes)
[11/Apr/2024 10:26:42] {charon} charon: 11[NET] received packet: from zyxelPublicIP[56107] to 192.168.40.2[4500] (60 bytes)
[11/Apr/2024 10:26:42] {charon} charon: 11[ENC] parsed QUICK_MODE request 2407479896 [ HASH ]
[11/Apr/2024 10:26:42] {charon} charon: 11[KNL] policy already exists, try to update it
[11/Apr/2024 10:26:42] {charon} Last message repeated 3 times
[11/Apr/2024 10:26:42] {charon} charon: 11[IKE] CHILD_SA tunnel_13_1_1_1{21374} established with SPIs c77fb2c7_i 8cdfb2f6_o and TS 10.0.0.0/8 === 192.168.29.0/24