hgonzale, what are the clients in your case?
The thing is that as this topic made me curious, I’ve started an L2TP/IPsec connection using the embedded VPN client of Windows 10 and used it so that there would be real traffic through the L2TP session, and it broke down as well. In my case, it didn’t take exactly 8 hours but something like 7:36 until the Windows client has decided to renew the IPsec phase 1, but it took it so long between tearing down the old one and starting to establish the new one that Mikrotik has managed to tear down the L2TP layer on inactivity in the meantime. See the commented tour below.
The DHCP lease time on the laptop side is 10 minutes so it is unlikely that this would be related, as there were tens of DHCP renewals which didn’t break the IPsec. So I’ll try another round during the night, this time with an Android device.
On top of that, there is no ISP involved - the laptop is connected using WiFi to one 'Tik (uptime much longer than between now and the L2TP breakdown), and the L2TP/IPsec connection passes through NATting OpenWRT device and gets to the other 'Tik which is the L2TP/IPsec server.
When the IPsec connection is initially established, the client declares sincerely the Phase 1 lifetime limitation to 8 hours:
11:22:22 ipsec,debug Compared: Local:Peer
11:22:22 ipsec,debug (lifetime = 86400:28800)
28800 seconds means 8 hours
11:22:22 ipsec,debug (lifebyte = 0:0)
11:22:22 ipsec,debug enctype = AES-CBC:AES-CBC
11:22:22 ipsec,debug (encklen = 256:256)
11:22:22 ipsec,debug hashtype = SHA:SHA
11:22:22 ipsec,debug authmethod = pre-shared key:pre-shared key
11:22:22 ipsec,debug dh_group = 2048-bit MODP group:2048-bit MODP group
11:22:22 ipsec,debug an acceptable proposal found.
After this, the connection establishes and just works, only Phase 2 is renegotiated from time to time without impact.
Nothing indicates a problem just before the breakdown:
18:57:21 ipsec,debug KA: 192.168.10.88[4500]->10.0.0.5[4500]
18:57:21 ipsec,debug 1 times of 1 bytes message will be sent to 10.0.0.5[4500]
18:57:21 ipsec,debug,packet ff
KA means KeepAlive and it is an IPsec keepalive here. These are sent three times a minute.
18:57:29 l2tp,debug,packet sent control message to 10.0.0.5:1701 from 192.168.10.88:1701
18:57:29 l2tp,debug,packet tunnel-id=5, session-id=0, ns=456, nr=4
18:57:29 l2tp,debug,packet (M) Message-Type=HELLO
18:57:29 l2tp,debug,packet rcvd control message (ack) from 10.0.0.5:1701 to 192.168.10.88:1701
18:57:29 l2tp,debug,packet tunnel-id=1263, session-id=0, ns=4, nr=457
This is an L2TP keepalive - the server sends HELLO and the client responds with ack. These are sent once a minute and they’re asynchronous to the IPsec KeepAlives
18:57:41 ipsec,debug KA: 192.168.10.88[4500]->10.0.0.5[4500]
18:57:41 ipsec,debug 1 times of 1 bytes message will be sent to 10.0.0.5[4500]
18:57:41 ipsec,debug,packet ff
18:58:01 ipsec,debug KA: 192.168.10.88[4500]->10.0.0.5[4500]
18:58:01 ipsec,debug 1 times of 1 bytes message will be sent to 10.0.0.5[4500]
18:58:01 ipsec,debug,packet ff
18:58:21 ipsec,debug KA: 192.168.10.88[4500]->10.0.0.5[4500]
18:58:21 ipsec,debug 1 times of 1 bytes message will be sent to 10.0.0.5[4500]
18:58:21 ipsec,debug,packet ff
Here below the trouble begins:
18:58:24 ipsec,debug ===== received 92 bytes from 10.0.0.5[4500] to 192.168.10.88[4500]
18:58:24 ipsec,debug,packet 2a859f74 83bfff84 66b1ac17 dc1967e4 08100501 227b959d 0000005c 35e16fc6
18:58:24 ipsec,debug,packet 227f11e3 5d1d573e 97169e66 7d53809e 1c2cf21d e2a39f2d 55a276b0 2f09b4b2
18:58:24 ipsec,debug,packet b9ccda68 403e04f4 d4f31281 4ab50866 ce73f92a 25b48241 04fba3be
18:58:24 ipsec,debug receive Information.
18:58:24 ipsec,debug compute IV for phase2
18:58:24 ipsec,debug phase1 last IV:
18:58:24 ipsec,debug 108b0de7 933fdadc c36cb287 3ee353ad 227b959d
18:58:24 ipsec,debug hash(sha1)
18:58:24 ipsec,debug encryption(aes)
18:58:24 ipsec,debug phase2 IV computed:
18:58:24 ipsec,debug c625865e d69af68e d7672100 66f32a20
18:58:24 ipsec,debug encryption(aes)
18:58:24 ipsec,debug IV was saved for next processing:
18:58:24 ipsec,debug 4ab50866 ce73f92a 25b48241 04fba3be
18:58:24 ipsec,debug encryption(aes)
18:58:24 ipsec,debug with key:
18:58:24 ipsec,debug 180cc989 150aa766 f2f526af bb0819cd c17f8f66 6632fc13 2eba948d c143a772
18:58:24 ipsec,debug decrypted payload by IV:
18:58:24 ipsec,debug c625865e d69af68e d7672100 66f32a20
18:58:24 ipsec,debug decrypted payload, but not trimed.
18:58:24 ipsec,debug 0c000018 7badbada 4bd6bb2c 2aaf50c0 56d9c747 d2b78da3 0000001c 00000001
18:58:24 ipsec,debug 01100001 2a859f74 83bfff84 66b1ac17 dc1967e4 00000000 00000000 00000000
18:58:24 ipsec,debug padding len=1
18:58:24 ipsec,debug skip to trim padding.
18:58:24 ipsec,debug decrypted.
18:58:24 ipsec,debug 2a859f74 83bfff84 66b1ac17 dc1967e4 08100501 227b959d 0000005c 0c000018
18:58:24 ipsec,debug 7badbada 4bd6bb2c 2aaf50c0 56d9c747 d2b78da3 0000001c 00000001 01100001
18:58:24 ipsec,debug 2a859f74 83bfff84 66b1ac17 dc1967e4 00000000 00000000 00000000
18:58:24 ipsec,debug HASH with:
18:58:24 ipsec,debug 227b959d 0000001c 00000001 01100001 2a859f74 83bfff84 66b1ac17 dc1967e4
18:58:24 ipsec,debug hmac(hmac_sha1)
18:58:24 ipsec,debug HASH computed:
18:58:24 ipsec,debug 7badbada 4bd6bb2c 2aaf50c0 56d9c747 d2b78da3
18:58:24 ipsec,debug hash validated.
18:58:24 ipsec,debug begin.
18:58:24 ipsec,debug seen nptype=8(hash) len=24
18:58:24 ipsec,debug seen nptype=12(delete) len=28
18:58:24 ipsec,debug succeed.
18:58:24 ipsec,debug 10.0.0.5 delete payload for protocol ISAKMP
So the client has sent us a request to delete the IPsec Phase 1 (ISAKMP), which consequently takes down Phase 2 (ESP in this case) as well.
18:58:24 ipsec,info purging ISAKMP-SA 192.168.10.88[4500]<=>10.0.0.5[4500] spi=2a859f7483bfff84:66b1ac17dc1967e4.
18:58:24 ipsec purged IPsec-SA proto_id=ESP spi=0xeb151c6
18:58:24 ipsec purged IPsec-SA proto_id=ESP spi=0x7670525
18:58:24 ipsec,debug an undead schedule has been deleted.
18:58:24 ipsec removing generated policy
The line above is important - as we’ve removed the policy, the L2TP packets won’t be matched and sent via the SA although it still exists by now.
18:58:24 ipsec purged ISAKMP-SA 192.168.10.88[4500]<=>10.0.0.5[4500] spi=2a859f7483bfff84:66b1ac17dc1967e4.
18:58:24 ipsec,debug purged SAs.
18:58:24 ipsec,info ISAKMP-SA deleted 192.168.10.88[4500]-10.0.0.5[4500] spi:2a859f7483bfff84:66b1ac17dc1967e4 rekey:1
18:58:24 ipsec KA remove: 192.168.10.88[4500]->10.0.0.5[4500]
18:58:24 ipsec,debug KA tree dump: 192.168.10.88[4500]->10.0.0.5[4500] (in_use=1)
18:58:24 ipsec,debug KA removing this one...
Demolition of the IPsec connection completed. The L2TP transport packets cannot get anywhere until the IPsec connection gets established again. But it’s almost the time to send an l2tp HELLO…
18:58:29 l2tp,debug,packet sent control message to 10.0.0.5:1701 from 192.168.10.88:1701
18:58:29 l2tp,debug,packet tunnel-id=5, session-id=0, ns=457, nr=4
18:58:29 l2tp,debug,packet (M) Message-Type=HELLO
18:58:30 l2tp,debug,packet sent control message to 10.0.0.5:1701 from 192.168.10.88:1701
18:58:30 l2tp,debug,packet tunnel-id=5, session-id=0, ns=457, nr=4
18:58:30 l2tp,debug,packet (M) Message-Type=HELLO
18:58:31 l2tp,debug,packet sent control message to 10.0.0.5:1701 from 192.168.10.88:1701
18:58:31 l2tp,debug,packet tunnel-id=5, session-id=0, ns=457, nr=4
18:58:31 l2tp,debug,packet (M) Message-Type=HELLO
18:58:33 l2tp,debug,packet sent control message to 10.0.0.5:1701 from 192.168.10.88:1701
18:58:33 l2tp,debug,packet tunnel-id=5, session-id=0, ns=457, nr=4
18:58:33 l2tp,debug,packet (M) Message-Type=HELLO
18:58:37 l2tp,debug,packet sent control message to 10.0.0.5:1701 from 192.168.10.88:1701
18:58:37 l2tp,debug,packet tunnel-id=5, session-id=0, ns=457, nr=4
18:58:37 l2tp,debug,packet (M) Message-Type=HELLO
18:58:45 l2tp,debug,packet sent control message to 10.0.0.5:1701 from 192.168.10.88:1701
18:58:45 l2tp,debug,packet tunnel-id=5, session-id=0, ns=457, nr=4
18:58:45 l2tp,debug,packet (M) Message-Type=HELLO
18:58:53 l2tp,debug tunnel 1263 received no replies, disconnecting
You can see that the L2TP HELLOs are retransmited, doubling the delay with each retransmission (0.5 s, 1s, 2s, 4s, 8s), so after 23.5s in total, the server gives up waiting for an ****
ack
and initiates the disconnection process.
18:58:53 l2tp,debug tunnel 1263 entering state: dead
18:58:53 l2tp,debug session 1 entering state: dead
18:58:53 l2tp,ppp,debug <10.0.0.5>: LCP lowerdown
18:58:53 l2tp,ppp,debug <10.0.0.5>: LCP closed
18:58:53 l2tp,ppp,debug <10.0.0.5>: CCP lowerdown
18:58:53 l2tp,ppp,debug <10.0.0.5>: BCP lowerdown
18:58:53 l2tp,ppp,debug <10.0.0.5>: BCP down event in starting state
18:58:53 l2tp,ppp,debug <10.0.0.5>: IPCP lowerdown
18:58:53 l2tp,ppp,debug <10.0.0.5>: IPCP closed
18:58:53 l2tp,ppp,debug <10.0.0.5>: IPV6CP lowerdown
18:58:53 l2tp,ppp,debug <10.0.0.5>: IPV6CP down event in starting state
18:58:53 l2tp,ppp,debug <10.0.0.5>: MPLSCP lowerdown
18:58:53 l2tp,ppp,debug <10.0.0.5>: CCP close
18:58:53 l2tp,ppp,debug <10.0.0.5>: BCP close
18:58:53 l2tp,ppp,debug <10.0.0.5>: IPCP close
18:58:53 l2tp,ppp,debug <10.0.0.5>: IPV6CP close
18:58:53 l2tp,ppp,debug <10.0.0.5>: MPLSCP close
18:58:53 l2tp,ppp,info l2tp-server-dedecek: terminating... - hungup
18:58:53 l2tp,ppp,debug <10.0.0.5>: LCP lowerdown
18:58:53 l2tp,ppp,debug <10.0.0.5>: LCP down event in starting state
18:58:53 l2tp,ppp,info,account dedecek logged out, 27387 24129137 55951331 123213 106836
18:58:53 l2tp,ppp,info l2tp-server-dedecek: disconnected
18:58:53 ipsec,debug unbind ::ffff:192.168.99.1
Three seconds later, which is 32 seconds after it has shot down the previous Phase 1, the client initiates establishment of a new session:
18:58:56 ipsec,debug ===== received 408 bytes from 10.0.0.5[4500] to 192.168.10.88[4500]
18:58:56 ipsec,debug,packet 42b08e69 f8f6c26e 00000000 00000000 01100200 00000000 00000198 0d0000d4
18:58:56 ipsec,debug,packet 00000001 00000001 000000c8 01010005 03000028 01010000 80010007 800e0100
18:58:56 ipsec,debug,packet 80020002 80040014 80030001 800b0001 000c0004 00007080 03000028 02010000
18:58:56 ipsec,debug,packet 80010007 800e0080 80020002 80040013 80030001 800b0001 000c0004 00007080
18:58:56 ipsec,debug,packet 03000028 03010000 80010007 800e0100 80020002 8004000e 80030001 800b0001
18:58:56 ipsec,debug,packet 000c0004 00007080 03000024 04010000 80010005 80020002 8004000e 80030001
18:58:56 ipsec,debug,packet 800b0001 000c0004 00007080 00000024 05010000 80010005 80020002 80040002
18:58:56 ipsec,debug,packet 80030001 800b0001 000c0004 00007080 0d000018 01528bbb c0069612 1849ab9a
18:58:56 ipsec,debug,packet 1c5b2a51 00000001 0d000018 1e2b5169 05991c7d 7c96fcbf b587e461 00000009
18:58:56 ipsec,debug,packet 0d000014 4a131c81 07035845 5c5728f2 0e95452f 0d000014 90cb8091 3ebb696e
18:58:56 ipsec,debug,packet 086381b5 ec427b1f 0d000014 4048b7d5 6ebce885 25e7de7f 00d6c2d3 0d000014
18:58:56 ipsec,debug,packet fb1de3cd f341b7ea 16b7e5be 0855f120 0d000014 26244d38 eddb61b3 172a36e3
18:58:56 ipsec,debug,packet d0cfb819 00000014 e3a5966a 76379fe7 07228231 e5ce8652
18:58:56 ipsec,debug Marking ports as changed
18:58:56 ipsec,debug Marking ports as changed
18:58:56 ipsec,debug ===
18:58:56 ipsec,info respond new phase 1 (Identity Protection): 192.168.10.88[4500]<=>10.0.0.5[4500]
It then took another 2 seconds until new SAs were negotiated and installed:
...
18:58:58 ipsec,debug call pk_sendupdate
18:58:58 ipsec,debug encryption(aes-cbc)
18:58:58 ipsec,debug hmac(sha1)
18:58:58 ipsec,debug call pfkey_send_update_nat
18:58:58 ipsec IPsec-SA established: ESP/Transport 10.0.0.5[4500]->192.168.10.88[4500] spi=0x1f67a4
18:58:58 ipsec,debug pfkey update sent.
18:58:58 ipsec,debug encryption(aes-cbc)
18:58:58 ipsec,debug hmac(sha1)
18:58:58 ipsec,debug call pfkey_send_add_nat
18:58:58 ipsec IPsec-SA established: ESP/Transport 192.168.10.88[4500]->10.0.0.5[4500] spi=0xf1a4f34
18:58:58 ipsec,debug pfkey add sent.
18:58:58 ipsec,debug ===== received 76 bytes from 10.0.0.5[4500] to 192.168.10.88[4500]
18:58:58 ipsec,debug,packet 2a859f74 83bfff84 66b1ac17 dc1967e4 08100501 db32ba58 0000004c f1e52518
18:58:58 ipsec,debug,packet baeb8459 5c9cdab5 29193055 b74da572 854a337a be9c47ed 70ba26e1 0004899f
18:58:58 ipsec,debug,packet e0e045e9 bfbb4850 fb354c32
18:58:58 ipsec 10.0.0.5 unknown Informational exchange received.
And it took another 8 seconds until the client started sending its own HELLO keepalives still within the old session (see the
ns
,
nr
values), which is however too late to help anything.
18:59:06 l2tp,debug,packet rcvd control message from 10.0.0.5:1701 to 192.168.10.88:1701
18:59:06 l2tp,debug,packet tunnel-id=1263, session-id=0, ns=4, nr=457
18:59:06 l2tp,debug,packet (M) Message-Type=HELLO
18:59:16 l2tp,debug,packet rcvd control message from 10.0.0.5:1701 to 192.168.10.88:1701
18:59:16 l2tp,debug,packet tunnel-id=1263, session-id=0, ns=4, nr=457
18:59:16 l2tp,debug,packet (M) Message-Type=HELLO
18:59:26 l2tp,debug,packet rcvd control message from 10.0.0.5:1701 to 192.168.10.88:1701
18:59:26 l2tp,debug,packet tunnel-id=1263, session-id=0, ns=4, nr=457
18:59:26 l2tp,debug,packet (M) Message-Type=HELLO
As Android client also limits the Phase 1 lifetime to 8 hours, I’ll first check how the renegotiation looks like in Android case, and then I’ll try whether configuring a shorter lifetime limit at RouterOS side won’t make the client(s) behave differently.