[Swan] Windows 10 client to libreswan VPN server: The Child SA expires often

Mirsad Goran Todorovac mirsad.todorovac at alu.unizg.hr
Mon Jan 10 21:34:04 EET 2022


On 1/9/2022 11:27 PM, Mirsad Goran Todorovac wrote:

> On 1/9/2022 10:51 PM, Paul Wouters wrote:
>
>> On Fri, 7 Jan 2022, Mirsad Goran Todorovac wrote:
>>
>>> 000 #5: "MYCONN-ikev2-cp"[3] 94.253.211.1:4500 
>>> STATE_V2_ESTABLISHED_IKE_SA (established IKE SA); EXPIRE in 25923s; 
>>> newest ISAKMP; idle;
>>> 000 #9: "MYCONN-ikev2-cp"[3] 94.253.211.1:4500 
>>> STATE_V2_ESTABLISHED_CHILD_SA (established Child SA); EXPIRE in 
>>> 28737s; newest IPSEC; eroute owner; isakmp#5; idle;
>>> 000 #9: "MYCONN-ikev2-cp"[3] 94.253.211.1 esp.c8c6721e at 94.253.211.1 
>>> esp.193db088 at 161.53.83.3 tun.0 at 94.253.211.1 tun.0 at 161.53.83.3 
>>> Traffic: ESPin=396KB ESPout=23MB ESPmax=0B
>>>
>>> What is the problem?
>>>
>>> The Child SA is renegotiated every about 5 minutes despite saying 
>>> EXPIRE in 28800 s.
>>
>> Is it expiring, or is the client rekeying it ? The logs should show you
>> which end is triggering this. If it is libreswan, there should be a
>> reason in the logs. If it is microsoft, then we can't help it. Microsoft
>> is known to aggressively clean up "idle" connections.

Actually, there seems to be a workaround, I just stumbled across: in 
"Change adapter options" the connection name is to be selected, then 
"Properties", then set this setting "Idle time before hanging up". 
Default is "never", but "never" means "300 seconds" for Microsoft, so I 
chose 30 minutes and so far it didn't break:

Every 1.0s: ipsec showstates domac: Mon Jan 10 20:28:13 2022

000 #74: "MYCONN-ikev2-cp"[14] 94.253.210.31:4500 
STATE_V2_ESTABLISHED_IKE_SA (established IKE SA); EXPIRE in 27898s; 
newest ISAKMP; idle;
000 #75: "MYCONN-ikev2-cp"[14] 94.253.210.31:4500 
STATE_V2_ESTABLISHED_CHILD_SA (established Child SA); EXPIRE in 27898s; 
newest IPSEC; eroute owner; isakmp#74; idle;
000 #75: "MYCONN-ikev2-cp"[14] 94.253.210.31 esp.89af0942 at 94.253.210.31 
esp.e0a86b6f at 161.53.235.3 tun.0 at 94.253.210.31 tun.0 at 161.53.235.3 
Traffic: ESPin=1MB ESPout=21MB ESPmax=0B

As you can probably see, countdown came to 27898s, while previously it 
was 28500s at most. :)

Probably having 8 hours as hangup time will have the Child SA expire 
when the IKE_SA expires, so it is good enough.
But more testing is required on Windows 10, and that's a growing amount 
of configuration from defaults on each client :-/

Hope this helps someone. I will additionally have to update 
configurations and revisit each configured client, for it is inexcusable 
if the accounting app disconnects after 300 seconds of work while 
renegotiating Child SA.

But I realize this is not libreswan fault, but MS client.

Kind regards,
Mirsad

>>
>> If you run "ipsec status" when the connection is up, it will show you
>> the timers for rekey/expire of the states (ipsec status |grep STATE_)
>
> Actually, it says about receiving DELETE payload and it is `executing 
> down-client` and then bringing client up, then executing entire 
> renegotiation of proposals, and considering certificates again ... 
> However, in `ipsec showstates`, only Child SA is shown as renegotiated ...
>
> The log is too copious to copy here, I will make it available here: 
> https://domac.alu.hr/mtodorov/ikev2-20220109-01.log
>
> The interesting event is around 23:11:56 (after 300 seconds of 
> connection):
>
> Jan  9 23:11:56.673641: | *received 80 bytes from 94.253.211.1:4500 on eth0 161.53.235.3:4500 using UDP
> Jan  9 23:11:56.673654: |   b9 fd 6d 9f  b2 16 af f5  7b 58 46 60  26 33 81 2a   ..m.....{XF`&3.*
> Jan  9 23:11:56.673664: |   2e 20 25 08  00 00 00 02  00 00 00 50  2a 00 00 34   . %........P*..4
> Jan  9 23:11:56.673680: |   a7 ef 87 ed  d2 b2 c5 41  f5 64 37 ea  b3 38 9e 3d   .......A.d7..8.=
> Jan  9 23:11:56.673704: |   c1 b9 49 2d  30 9f d9 df  f4 61 f5 c7  3f c0 e8 cb   ..I-0....a..?...
> Jan  9 23:11:56.673721: |   bc 9d 28 05  81 94 50 da  0e 76 0d b1  cd 5e c0 fb   ..(...P..v...^..
> Jan  9 23:11:56.673745: | **parse ISAKMP Message:
> Jan  9 23:11:56.673772: |    initiator SPI: b9 fd 6d 9f  b2 16 af f5
> Jan  9 23:11:56.673797: |    responder SPI: 7b 58 46 60  26 33 81 2a
> Jan  9 23:11:56.673819: |    next payload type: ISAKMP_NEXT_v2SK (0x2e)
> Jan  9 23:11:56.673838: |    ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)
> Jan  9 23:11:56.673880: |    exchange type: ISAKMP_v2_INFORMATIONAL (0x25)
> Jan  9 23:11:56.673904: |    flags: ISAKMP_FLAG_v2_IKE_INIT (0x8)
> Jan  9 23:11:56.673928: |    Message ID: 2 (00 00 00 02)
> Jan  9 23:11:56.673951: |    length: 80 (00 00 00 50)
> Jan  9 23:11:56.673972: |  processing version=2.0 packet with exchange type=ISAKMP_v2_INFORMATIONAL (37)
> Jan  9 23:11:56.673994: | I am the IKE SA Original Responder receiving an IKEv2 INFORMATIONAL request
> Jan  9 23:11:56.674019: | State DB: found IKEv2 state #8 in ESTABLISHED_IKE_SA (find_v2_ike_sa)
> Jan  9 23:11:56.674045: | #8 st.st_msgid_lastrecv 1 md.hdr.isa_msgid 00000002
> Jan  9 23:11:56.674067: | found #8 for (find_v2_sa_by_responder_wip() +1043 programs/pluto/ikev2.c)
> Jan  9 23:11:56.674086: | found #9 for (find_v2_sa_by_responder_wip() +1043 programs/pluto/ikev2.c)
> Jan  9 23:11:56.674105: | no match for (find_v2_sa_by_responder_wip() +1043 programs/pluto/ikev2.c)
> Jan  9 23:11:56.674123: | #8 is idle
> Jan  9 23:11:56.674156: | Message ID: IKE #8 not a duplicate - message request 2 is new: ike.initiator.sent=-1 ike.initiator.recv=-1 ike.initiator.last_contact=9249384.238938 ike.responder.sent=1 ike.responder.recv=1 ike.responder.last_contact=9249084.269439 ike.wip.initiator=-1 ike.wip.responder=-1
> Jan  9 23:11:56.674174: | unpacking clear payload
> Jan  9 23:11:56.674196: | Now let's proceed with payload (ISAKMP_NEXT_v2SK)
> Jan  9 23:11:56.674217: | ***parse IKEv2 Encryption Payload:
> Jan  9 23:11:56.674237: |    next payload type: ISAKMP_NEXT_v2D (0x2a)
> Jan  9 23:11:56.674254: |    flags: none (0x0)
> Jan  9 23:11:56.674275: |    length: 52 (00 34)
> Jan  9 23:11:56.674294: | processing payload: ISAKMP_NEXT_v2SK (len=48)
> Jan  9 23:11:56.674315: | #8 in state ESTABLISHED_IKE_SA: established IKE SA
> Jan  9 23:11:56.674389: |     result: newref clone-key at 0x564a2009f720 (32-bytes, SHA256_HMAC)(init_symkey() +99 lib/libswan/ike_alg_prf_mac_nss_ops.c)
> Jan  9 23:11:56.674439: | auth: delref clone-key at 0x564a2009f720
> Jan  9 23:11:56.674494: | authenticator matched
> Jan  9 23:11:56.674554: | stripping 4 octets as pad
> Jan  9 23:11:56.674579: | #8 ikev2 ISAKMP_v2_INFORMATIONAL decrypt success
> Jan  9 23:11:56.674597: | Now let's proceed with payload (ISAKMP_NEXT_v2D)
> Jan  9 23:11:56.674618: | **parse IKEv2 Delete Payload:
> Jan  9 23:11:56.674637: |    next payload type: ISAKMP_NEXT_v2NONE (0x0)
> Jan  9 23:11:56.674654: |    flags: none (0x0)
> Jan  9 23:11:56.674675: |    length: 12 (00 0c)
> Jan  9 23:11:56.674692: |    protocol ID: IKEv2_SEC_PROTO_ESP (0x3)
> Jan  9 23:11:56.674710: |    SPI size: 4 (04)
> Jan  9 23:11:56.674731: |    number of SPIs: 1 (00 01)
> Jan  9 23:11:56.674751: | processing payload: ISAKMP_NEXT_v2D (len=4)
> Jan  9 23:11:56.674769: | selected state microcode Informational Request
> Jan  9 23:11:56.674798: | Message ID: IKE #8 responder starting message request 2: ike.initiator.sent=-1 ike.initiator.recv=-1 ike.initiator.last_contact=9249384.238938 ike.responder.sent=1 ike.responder.recv=1 ike.responder.last_contact=9249084.269439 ike.wip.initiator=-1 ike.wip.responder=-1->2
> Jan  9 23:11:56.674818: | calling processor Informational Request
> Jan  9 23:11:56.674843: |   #8 spent 1.31 (1.31) milliseconds
> Jan  9 23:11:56.674862: | an informational request needing a response
> Jan  9 23:11:56.674939: | opening output PBS information exchange reply packet
> Jan  9 23:11:56.674957: | **emit ISAKMP Message:
> Jan  9 23:11:56.674973: |    initiator SPI: b9 fd 6d 9f  b2 16 af f5
> Jan  9 23:11:56.674996: |    responder SPI: 7b 58 46 60  26 33 81 2a
> Jan  9 23:11:56.675015: |    next payload type: ISAKMP_NEXT_NONE (0x0)
> Jan  9 23:11:56.675034: |    ISAKMP version: IKEv2 version 2.0 (rfc4306/rfc5996) (0x20)
> Jan  9 23:11:56.675051: |    exchange type: ISAKMP_v2_INFORMATIONAL (0x25)
> Jan  9 23:11:56.675071: |    flags: ISAKMP_FLAG_v2_MSG_RESPONSE (0x20)
> Jan  9 23:11:56.675094: |    Message ID: 2 (00 00 00 02)
> Jan  9 23:11:56.675113: | next payload chain: saving message location 'ISAKMP Message'.'next payload type'
> Jan  9 23:11:56.675133: | ***emit IKEv2 Encryption Payload:
> Jan  9 23:11:56.675152: |    next payload type: ISAKMP_NEXT_v2NONE (0x0)
> Jan  9 23:11:56.675188: |    flags: none (0x0)
> Jan  9 23:11:56.675211: | next payload chain: setting previous 'ISAKMP Message'.'next payload type' to current IKEv2 Encryption Payload (46:ISAKMP_NEXT_v2SK)
> Jan  9 23:11:56.675229: | next payload chain: saving location 'IKEv2 Encryption Payload'.'next payload type' in 'information exchange reply packet'
> Jan  9 23:11:56.675250: | emitting 16 zero bytes of IV into IKEv2 Encryption Payload
> Jan  9 23:11:56.675293: | parsing 4 raw bytes of IKEv2 Delete Payload into SPI
>
> Hope this helps,
> Mirsad
>
> --
> Mirsad Goran Todorovac
> CARNet sistem inženjer
> Grafički fakultet | Akademija likovnih umjetnosti
> Sveučilište u Zagrebu
> -- 
> CARNet system engineer
> Faculty of Graphic Arts | Academy of Fine Arts
> University of Zagreb, Republic of Croatia
> tel. +385 (0)1 3711 451
> mob. +385 91 57 88 355
>
> _______________________________________________
> Swan mailing list
> Swan at lists.libreswan.org
> https://lists.libreswan.org/mailman/listinfo/swan

--
Mirsad Goran Todorovac
CARNet sistem inženjer
Grafički fakultet | Akademija likovnih umjetnosti
Sveučilište u Zagrebu
-- 
CARNet system engineer
Faculty of Graphic Arts | Academy of Fine Arts
University of Zagreb, Republic of Croatia
tel. +385 (0)1 3711 451
mob. +385 91 57 88 355
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20220110/47ed04b2/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: NM0okaIvW9IrJ9DC.png
Type: image/png
Size: 9424 bytes
Desc: not available
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20220110/47ed04b2/attachment-0001.png>


More information about the Swan mailing list