<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
<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" href="mailto:esp.c8c6721e@94.253.211.1">esp.c8c6721e@94.253.211.1</a> <a class="moz-txt-link-abbreviated" href="mailto:esp.193db088@161.53.83.3">esp.193db088@161.53.83.3</a>
<a class="moz-txt-link-abbreviated" href="mailto:tun.0@94.253.211.1">tun.0@94.253.211.1</a> <a class="moz-txt-link-abbreviated" href="mailto:tun.0@161.53.83.3">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>
<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">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>
</body>
</html>