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 [email protected]
[email protected] [email protected] [email protected]
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.
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@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
--
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
[email protected]
https://lists.libreswan.org/mailman/listinfo/swan
