<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
<p>On 1/9/2022 11:27 PM, Mirsad Goran Todorovac wrote:<br>
</p>
<blockquote type="cite"
cite="mid:e741e451-a3f9-8d14-54c7-24e38ded078a@alu.unizg.hr">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
<p>On 1/9/2022 10:51 PM, Paul Wouters wrote:<br>
</p>
<blockquote type="cite"
cite="mid:501fa045-7c56-f61f-c52d-37ea10e04160@nohats.ca">On
Fri, 7 Jan 2022, Mirsad Goran Todorovac wrote: <br>
<br>
<blockquote type="cite">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; <br>
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; <br>
000 #9: "MYCONN-ikev2-cp"[3] 94.253.211.1 <a
class="moz-txt-link-abbreviated moz-txt-link-freetext"
href="mailto:esp.c8c6721e@94.253.211.1"
moz-do-not-send="true">esp.c8c6721e@94.253.211.1</a> <a
class="moz-txt-link-abbreviated moz-txt-link-freetext"
href="mailto:esp.193db088@161.53.83.3"
moz-do-not-send="true">esp.193db088@161.53.83.3</a> <a
class="moz-txt-link-abbreviated moz-txt-link-freetext"
href="mailto:tun.0@94.253.211.1" moz-do-not-send="true">tun.0@94.253.211.1</a>
<a class="moz-txt-link-abbreviated moz-txt-link-freetext"
href="mailto:tun.0@161.53.83.3" moz-do-not-send="true">tun.0@161.53.83.3</a>
Traffic: ESPin=396KB ESPout=23MB ESPmax=0B <br>
<br>
What is the problem? <br>
<br>
The Child SA is renegotiated every about 5 minutes despite
saying EXPIRE in 28800 s. <br>
</blockquote>
<br>
Is it expiring, or is the client rekeying it ? The logs should
show you <br>
which end is triggering this. If it is libreswan, there should
be a <br>
reason in the logs. If it is microsoft, then we can't help it.
Microsoft <br>
is known to aggressively clean up "idle" connections. <br>
</blockquote>
</blockquote>
<p>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:<br>
</p>
<p><img src="cid:part1.Dgbg875s.1vHottba@alu.unizg.hr" alt=""
width="297" height="363"></p>
<p><font size="1" face="monospace">Every 1.0s: ipsec
showstates
domac: Mon Jan 10 20:28:13 2022<br>
<br>
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;<br>
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;<br>
000 #75: "MYCONN-ikev2-cp"[14] 94.253.210.31
<a class="moz-txt-link-abbreviated" href="mailto:esp.89af0942@94.253.210.31">esp.89af0942@94.253.210.31</a> <a class="moz-txt-link-abbreviated" href="mailto:esp.e0a86b6f@161.53.235.3">esp.e0a86b6f@161.53.235.3</a>
<a class="moz-txt-link-abbreviated" href="mailto:tun.0@94.253.210.31">tun.0@94.253.210.31</a> <a class="moz-txt-link-abbreviated" href="mailto:tun.0@161.53.235.3">tun.0@161.53.235.3</a> Traffic: ESPin=1MB
ESPout=21MB ESPmax=0B<br>
</font><br>
As you can probably see, countdown came to 27898s, while
previously it was 28500s at most. :)</p>
<p>Probably having 8 hours as hangup time will have the Child SA
expire when the IKE_SA expires, so it is good enough.<br>
But more testing is required on Windows 10, and that's a growing
amount of configuration from defaults on each client :-/</p>
<p>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.</p>
<p>But I realize this is not libreswan fault, but MS client.<br>
</p>
<p>Kind regards,<br>
Mirsad<br>
</p>
<blockquote type="cite"
cite="mid:e741e451-a3f9-8d14-54c7-24e38ded078a@alu.unizg.hr">
<blockquote type="cite"
cite="mid:501fa045-7c56-f61f-c52d-37ea10e04160@nohats.ca"> <br>
If you run "ipsec status" when the connection is up, it will
show you <br>
the timers for rekey/expire of the states (ipsec status |grep
STATE_) <br>
</blockquote>
<p>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 ...<br>
</p>
<p>The log is too copious to copy here, I will make it available
here: <a class="moz-txt-link-freetext"
href="https://domac.alu.hr/mtodorov/ikev2-20220109-01.log"
moz-do-not-send="true">https://domac.alu.hr/mtodorov/ikev2-20220109-01.log</a></p>
<p>The interesting event is around 23:11:56 (after 300 seconds of
connection):</p>
<pre>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@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@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
</pre>
<pre class="moz-signature" cols="72">--
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</pre>
<br>
<fieldset class="moz-mime-attachment-header"></fieldset>
<pre class="moz-quote-pre" wrap="">_______________________________________________
Swan mailing list
<a class="moz-txt-link-abbreviated" href="mailto:Swan@lists.libreswan.org">Swan@lists.libreswan.org</a>
<a class="moz-txt-link-freetext" href="https://lists.libreswan.org/mailman/listinfo/swan">https://lists.libreswan.org/mailman/listinfo/swan</a>
</pre>
</blockquote>
<pre class="moz-signature" cols="72">--
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</pre>
</body>
</html>