[Swan] Problem with random rekey failures
Miguel Ponce Antolin
mponce at paradigmadigital.com
Tue Jun 15 13:39:02 UTC 2021
Hi,
In order to add more information.
At this time libreswan is working well, this is a log segment extracted
from ipsec status which shows a rightsubnet (vpn/1x9) that is without the
phase 2 active but has tried to reconnect at some moment after the subnet
phase 2 went down:
20210615_T14:19:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=2s; idle; import:admin
initiate
20210615_T14:20:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=2s; idle; import:admin
initiate
20210615_T14:21:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=22s; idle; import:admin
initiate
At this point we sent some traffic trying to reconnect the subnet which
successfully get the #207 number, but doesn't delete the previous attempt
with state STATE_V2_REKEY_CHILD_I0:
20210615_T14:22:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=82s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27920s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:23:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=10s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27860s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:24:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=2s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27800s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:25:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27740s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:26:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=0s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27680s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:27:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=16s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27620s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:28:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27560s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:29:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27500s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:30:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=7s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27439s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:31:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27380s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:32:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27320s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:33:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27260s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:34:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=16s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27200s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:35:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27140s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:36:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27080s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:37:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 27020s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:38:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26960s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:39:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=7s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26899s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:40:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26840s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:41:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26780s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:42:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26719s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:43:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26659s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:44:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=7s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26599s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:45:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26540s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:46:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26480s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:47:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26420s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:48:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26360s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:49:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26300s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:50:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26240s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:51:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26180s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
20210615_T14:52:02 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=4s; idle; import:admin
initiate
000 #207: "vpn/1x9":500 STATE_V2_IPSEC_I (IPsec SA established);
EVENT_SA_REPLACE in 26119s; newest IPSEC; eroute owner; isakmp#169; idle;
import:admin initiate
After 30 minutes the subnet phase 2 goes down again and retryes using the
new #227 which is not successful reconnected. Anyway the old #56 is blocked
for some reason:
20210615_T14:53:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=3s; idle; import:admin
initiate
000 #227: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0 (STATE_V2_REKEY_CHILD_I0);
EVENT_CRYPTO_TIMEOUT in 56s; lastlive=3s; idle; import:admin initiate
20210615_T14:54:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=11s; idle; import:admin
initiate
20210615_T14:55:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=2s; idle; import:admin
initiate
20210615_T14:56:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=2s; idle; import:admin
initiate
20210615_T14:57:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=6s; idle; import:admin
initiate
20210615_T14:58:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=2s; idle; import:admin
initiate
20210615_T14:59:01 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=12s; idle; import:admin
initiate
20210615_T15:00:03 - 000 #56: "vpn/1x9":500 STATE_V2_REKEY_CHILD_I0
(STATE_V2_REKEY_CHILD_I0); none in -1s; lastlive=14s; idle; import:admin
initiate
Other logs from the pluto.log on this events filtering with (grep -e "#56"
-e "vpn/1x9" -e "#207" -e "#227") and omiting repeated lines with (...), I
hope it helps:
1 Jun 15 14:18:01.044603: | pending review: connection "vpn/1x9" checked
2 Jun 15 14:20:01.047861: | pending review: connection "vpn/1x9" checked
3 Jun 15 14:20:41.789100: | conn vpn/1x9 mark 0/00000000, 0/00000000
4 ...
5 Jun 15 14:21:12.518678: | conn vpn/1x9 mark 0/00000000, 0/00000000
6 Jun 15 14:21:21.368267: | find_connection: conn "vpn/1x9" has
compatible peers: xxx.xxx.xxx.80/28 -> xxx.xxx.xxx.166/32 [pri: 29425674]
7 Jun 15 14:21:21.368271: | find_connection: first OK "vpn/1x9"
[pri:29425674]{0x5631587fe078} (child none)
8 Jun 15 14:21:21.368280: | find_connection: concluding with "vpn/1x9"
[pri:29425674]{0x5631587fe078} kind=CK_PERMANENT
9 Jun 15 14:21:21.368292: | priority calculation of connection "vpn/1x9"
is 0xfe3df
10 Jun 15 14:21:21.368381: | creating state object #207 at 0x56315882f608
11 Jun 15 14:21:21.368385: | parent state #207: new =>
STATE_UNDEFINED(ignore)
12 Jun 15 14:21:21.368389: | duplicating state object #169 "vpn/1x18" as
#207 for IPSEC SA
13 Jun 15 14:21:21.368405: "vpn/1x9" #207: extra debugging enabled for
connection: none
14 Jun 15 14:21:21.368412: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_initiate_child_sa() at
ikev2_parent.c:6767)
15 Jun 15 14:21:21.368425: | child state #207: STATE_UNDEFINED(ignore) =>
STATE_V2_CREATE_I0(established-authenticated-ike)
16 Jun 15 14:21:21.368461: | inserting state object #207
17 Jun 15 14:21:21.368466: | serialno list: inserting object
0x56315882f608 (state #207) entry 0x56315882fdb0 into list 0x563157ba4840
(older 0x56315882b050 newer 0x5631588564c0)
18 Jun 15 14:21:21.368471: | serialno list: inserted object
0x56315882f608 (state #207) entry 0x56315882fdb0 (older 0x56315882b050
newer 0x563157ba4840)
19 Jun 15 14:21:21.368479: | serialno table: inserting object
0x56315882f608 (state #207) entry 0x56315882fdd0 into list 0x563157b99140
(older 0x563157b99140 newer 0x563157b99140)
20 Jun 15 14:21:21.368485: | serialno table: inserted object
0x56315882f608 (state #207) entry 0x56315882fdd0 (older 0x563157b99140
newer 0x563157b99140)
21 Jun 15 14:21:21.368509: | constructing ESP/AH proposals with default DH
MODP2048 for vpn/1x9 (ESP/AH initiator emitting proposals)
22 Jun 15 14:21:21.368529: "vpn/1x9" #207: local ESP/AH proposals for
vpn/1x9 (ESP/AH initiator emitting proposals):
1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048;ESN=DISABLED
23 Jun 15 14:21:21.368536: | #207 schedule initiate IPsec SA
PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV2_ALLOW+IKEV2_PROPOSE+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
using IKE# 169 pfs=MODP2048
24 Jun 15 14:21:21.368540: | state #207 requesting to delete non existing
event
25 Jun 15 14:21:21.368549: | inserting event EVENT_v2_INITIATE_CHILD,
timeout in 0.000 seconds for #207
26 Jun 15 14:21:21.368557: | processing: RESET state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_initiate_child_sa() at
ikev2_parent.c:6862)
27 Jun 15 14:21:21.368581: | handling event EVENT_v2_INITIATE_CHILD for
child state #207
28 Jun 15 14:21:21.368585: "vpn/1x9" #207: extra debugging enabled for
connection: none
29 Jun 15 14:21:21.368592: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
30 Jun 15 14:21:21.368608: | adding Child Initiator KE and nonce ni
work-order 318 for state #207
31 Jun 15 14:21:21.368612: | state #207 requesting to delete non existing
event
32 Jun 15 14:21:21.368650: | inserting event EVENT_CRYPTO_TIMEOUT, timeout
in 60.000 seconds for #207
33 Jun 15 14:21:21.368656: | backlog: inserting object 0x56315882ffd8
(work-order 318 state #207) entry 0x56315882ffe0 into list 0x563157ba5740
(older 0x563157ba5740 newer 0x563157ba5740)
34 Jun 15 14:21:21.368661: | backlog: inserted object 0x56315882ffd8
(work-order 318 state #207) entry 0x56315882ffe0 (older 0x563157ba5740
newer 0x563157ba5740)
35 Jun 15 14:21:21.368689: | backlog: removing object 0x56315882ffd8
(work-order 318 state #207) entry 0x56315882ffe0 (older 0x563157ba5740
newer 0x563157ba5740)
36 Jun 15 14:21:21.368699: | crypto helper 0 starting work-order 318 for
state #207
37 Jun 15 14:21:21.370373: | crypto helper 0 sending results from
work-order 318 for state #207 to event queue
38 Jun 15 14:21:21.370379: | scheduling now-event sending helper answer
for #207
39 Jun 15 14:21:21.370408: | processing: stop state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:669)
40 Jun 15 14:21:21.370429: | serialno table: hash serialno #207 to head
0x563157b99140
41 Jun 15 14:21:21.370432: | serialno table: hash serialno #207 to head
0x563157b99140
42 Jun 15 14:21:21.370436: "vpn/1x9" #207: extra debugging enabled for
connection: none
43 Jun 15 14:21:21.370441: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:594)
44 Jun 15 14:21:21.370451: | ikev2_crypto_continue for #207
45 Jun 15 14:21:21.370464: | #207 send new exchange now using parent #169
unacknowledged 0 next message id=73 ike exchange window 1
46 Jun 15 14:21:21.370468: "vpn/1x9" #207: extra debugging enabled for
connection: none
47 Jun 15 14:21:21.370473: | processing: [RE]START state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_child_out_cont() at
ikev2_parent.c:5815)
48 Jun 15 14:21:21.371176: "vpn/1x9" #207: extra debugging enabled for
connection: none
49 Jun 15 14:21:21.371181: | processing: [RE]START state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in complete_v2_state_transition() at
ikev2.c:2787)
50 Jun 15 14:21:21.371185: | #207 complete v2 state transition from
STATE_V2_CREATE_I0 with STF_OK
51 Jun 15 14:21:21.371200: | child state #207:
STATE_V2_CREATE_I0(established-authenticated-ike) =>
STATE_V2_CREATE_I(established-authenticated-ike)
52 Jun 15 14:21:21.371244: | message ID #207 STATE_V2_CREATE_I vpn/1x9 pst
#169 st_msgid_nextuse(before=73) 74 st_msgid_lastack 72 st_msgid_lastrecv
4294967295 md is a request
53 Jun 15 14:21:21.371248: "vpn/1x9" #207: STATE_V2_CREATE_I: sent IPsec
Child req wait response
54 Jun 15 14:21:21.371385: | state #207 requesting EVENT_CRYPTO_TIMEOUT to
be deleted
55 Jun 15 14:21:21.371405: | inserting event EVENT_v2_RETRANSMIT, timeout
in 0.500 seconds for #207
56 Jun 15 14:21:21.371411: | #207 STATE_V2_CREATE_I: retransmits: first
event in 0.5 seconds; timeout in 60 seconds; limit of 12 retransmits;
current time is 1750825.454
57 Jun 15 14:21:21.371417: | processing: stop state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:597)
58 Jun 15 14:21:21.407522: | v2 peer, cookies and msgid match on #207
59 Jun 15 14:21:21.407526: | v2 state object #207 found, in
STATE_V2_CREATE_I
60 Jun 15 14:21:21.407529: | found state #207
61 Jun 15 14:21:21.407534: "vpn/1x9" #207: extra debugging enabled for
connection: none
62 Jun 15 14:21:21.407540: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_process_packet() at ikev2.c:1538)
63 Jun 15 14:21:21.407543: "vpn/1x9" #207: extra debugging enabled for
connection: none
64 Jun 15 14:21:21.407547: | processing: start connection "vpn/1x9"
(BACKGROUND) (in ikev2_process_packet() at ikev2.c:1543)
65 Jun 15 14:21:21.407558: | #207 is idle
66 Jun 15 14:21:21.407561: | #207 idle
67 Jun 15 14:21:21.407565: | #207 in state V2_CREATE_I: sent IPsec Child
req wait response
68 Jun 15 14:21:21.407793: | #207 ikev2 ISAKMP_v2_CREATE_CHILD_SA decrypt
success
69 Jun 15 14:21:21.407932: | "vpn/1x18" #169 received Child SA Response
CREATE_CHILD_SA from xxx.xxx.xxx.45:500 Child "vpn/1x9" #207 in
STATE_V2_CREATE_I will process it further
70 Jun 15 14:21:21.407935: | switching from parent? #207 to child #207 in
FSM processor
71 Jun 15 14:21:21.407947: | message ID #207 STATE_V2_CREATE_I vpn/1x9 pst
#169 st_msgid_nextuse(before=74) 74 st_msgid_lastack 73 st_msgid_lastrecv
4294967295 md is a resonse
72 Jun 15 14:21:21.407966: | already determined local ESP/AH proposals for
vpn/1x9 (ESP/AH initiator accepting remote proposal)
73 Jun 15 14:21:21.408170: | updating #207's .st_oakley with preserved
PRF, but why update?
74 Jun 15 14:21:21.408193: | adding ikev2 Child SA initiator pfs=yes
work-order 319 for state #207
75 Jun 15 14:21:21.408197: | state #207 requesting EVENT_v2_RETRANSMIT to
be deleted
76 Jun 15 14:21:21.408200: | #207 STATE_V2_CREATE_I: retransmits: cleared
77 Jun 15 14:21:21.408215: | inserting event EVENT_CRYPTO_TIMEOUT, timeout
in 60.000 seconds for #207
78 Jun 15 14:21:21.408222: | backlog: inserting object 0x56315882ffd8
(work-order 319 state #207) entry 0x56315882ffe0 into list 0x563157ba5740
(older 0x563157ba5740 newer 0x563157ba5740)
79 Jun 15 14:21:21.408227: | backlog: inserted object 0x56315882ffd8
(work-order 319 state #207) entry 0x56315882ffe0 (older 0x563157ba5740
newer 0x563157ba5740)
80 Jun 15 14:21:21.408340: | backlog: removing object 0x56315882ffd8
(work-order 319 state #207) entry 0x56315882ffe0 (older 0x563157ba5740
newer 0x563157ba5740)
81 Jun 15 14:21:21.408381: | crypto helper 1 starting work-order 319 for
state #207
82 Jun 15 14:21:21.409780: | crypto helper 1 sending results from
work-order 319 for state #207 to event queue
83 Jun 15 14:21:21.409805: | scheduling now-event sending helper answer
for #207
84 Jun 15 14:21:21.409850: | suspending state #207 and saving MD
85 Jun 15 14:21:21.409869: | #207 is busy; has a suspended MD
86 Jun 15 14:21:21.409888: "vpn/1x9" #207: extra debugging enabled for
connection: none
87 Jun 15 14:21:21.409909: | processing: [RE]START state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in log_stf_suspend() at ikev2.c:2691)
88 Jun 15 14:21:21.409929: | "vpn/1x9" #207 complete v2 state
STATE_V2_CREATE_I transition with STF_SUSPEND suspended from
complete_v2_state_transition:2763
89 Jun 15 14:21:21.409968: | processing: stop state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in process_md() at demux.c:396)
90 Jun 15 14:21:21.410023: "vpn/1x9": extra debugging enabled for
connection: none
91 Jun 15 14:21:21.410042: | processing: resume connection "vpn/1x9" (in
process_md() at demux.c:396)
92 Jun 15 14:21:21.410060: | processing: stop connection "vpn/1x9" (in
process_md() at demux.c:397)
93 Jun 15 14:21:21.410107: | serialno table: hash serialno #207 to head
0x563157b99140
94 Jun 15 14:21:21.410125: | serialno table: hash serialno #207 to head
0x563157b99140
95 Jun 15 14:21:21.410143: "vpn/1x9" #207: extra debugging enabled for
connection: none
96 Jun 15 14:21:21.410163: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:594)
97 Jun 15 14:21:21.410217: | ikev2_crypto_continue for #207
98 Jun 15 14:21:21.410727: | ikev2_evaluate_connection_fit evaluating
our conn="vpn/1x9" I=xxx.xxx.xxx.80/28:0/0 R=xxx.xxx.xxx.166/32:0/0 to
their:
99 Jun 15 14:21:21.410807: | prefix fitness found a better match c vpn/1x9
100 Jun 15 14:21:21.410899: | port fitness found better match c vpn/1x9,
tsi[0],tsr[0]
101 Jun 15 14:21:21.410990: | protocol fitness found better match c
vpn/1x9, tsi[0],tsr[0]
102 Jun 15 14:21:21.411447: | install_ipsec_sa() for #207: inbound and
outbound
103 Jun 15 14:21:21.411473: | could_route called for vpn/1x9
(kind=CK_PERMANENT)
104 Jun 15 14:21:21.411493: | conn vpn/1x9 mark 0/00000000, 0/00000000 vs
105 ...
106 Jun 15 14:21:21.412124: | conn vpn/1x9 mark 0/00000000, 0/00000000 vs
107 Jun 15 14:21:21.412161: | route owner of "vpn/1x9" prospective erouted:
self; eroute owner: self
108 Jun 15 14:21:21.412721: | priority calculation of connection "vpn/1x9"
is 0xfe3df
109 Jun 15 14:21:21.412924: | sr for #207: prospective erouted
110 Jun 15 14:21:21.412961: | conn vpn/1x9 mark 0/00000000, 0/00000000 vs
111 ...
112 Jun 15 14:21:21.413585: | conn vpn/1x9 mark 0/00000000, 0/00000000 vs
113 Jun 15 14:21:21.413622: | route owner of "vpn/1x9" prospective erouted:
self; eroute owner: self
114 Jun 15 14:21:21.413642: | route_and_eroute with c: vpn/1x9 (next: none)
ero:vpn/1x9 esr:{(nil)} ro:vpn/1x9 rosr:{(nil)} and state: #207
115 Jun 15 14:21:21.413661: | priority calculation of connection "vpn/1x9"
is 0xfe3df
116 Jun 15 14:21:21.413912: | executing up-client: PLUTO_VERB='up-client'
PLUTO_VERSION='2.0' PLUTO_CONNECTION='vpn/1x9' PLUTO_INTERFACE='eth0'
PLUTO_NEXT_HOP='xxx.xxx.xxx.81' PLUTO_ME='xxx.xxx.xxx.92'
PLUTO_MY_ID='54.247.44.120' PLUTO_MY_CLIENT='xxx.xxx.xxx.80/28' PLUTO_MY
_CLIENT_NET='xxx.xxx.xxx.80' PLUTO_MY_CLIENT_MASK='255.255.255.240'
PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_SA_REQID='16420'
PLUTO_SA_TYPE='ESP' PLUTO_PEER='xxx.xxx.xxx.45'
PLUTO_PEER_ID='xxx.xxx.xxx.45' PLUTO_PEER_CLIENT='xxx.xxx.xxx.166/32'
PLUTO_PEER_CLIENT_NET ='xxx.xxx.xxx.166'
PLUTO_PEER_CLIENT_MASK='255.255.255.255' PLUTO_PEER_PORT='0'
PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey'
PLUTO_ADDTIME='1623759681'
PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV2_ALLOW+IKEV2_PROPOSE+SAREF_TRACK+IKE_FRAG_ALLOW+ESN
_NO' PLUTO_CONN_KIND='CK_PERMANENT' PLUTO_CONN_ADDRFAMILY='ipv4'
XAUTH_FAILED=0 PLUTO_MY_SOURCEIP='xxx.xxx.xxx.92' PLUTO_IS_PEER_CISCO='0'
PLUTO_PEER_DNS_INFO='' PLUTO_PEER_DOMAIN_INFO='' PLUTO_PEER_BANNER=''
PLUTO_CFG_SERVER='0' PLUTO_CFG_CLIENT='0
117 Jun 15 14:21:21.413951: | cmd( 0):PLUTO_VERB='up-client'
PLUTO_VERSION='2.0' PLUTO_CONNECTION='vpn/1x9' PLUTO_INTE:
118 Jun 15 14:21:21.426748: | route_and_eroute: instance "vpn/1x9", setting
eroute_owner {spd=0x5631587fe180,sr=0x5631587fe180} to #207 (was #0)
(newest_ipsec_sa=#0)
119 Jun 15 14:21:21.426846: | inR2: instance vpn/1x9[0], setting IKEv2
newest_ipsec_sa to #207 (was #0) (spd.eroute=#207) cloned from #169
120 Jun 15 14:21:21.426873: | state #207 requesting EVENT_CRYPTO_TIMEOUT to
be deleted
121 Jun 15 14:21:21.426925: "vpn/1x9" #207: extra debugging enabled for
connection: none
122 Jun 15 14:21:21.426948: | processing: [RE]START state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in complete_v2_state_transition() at
ikev2.c:2787)
123 Jun 15 14:21:21.426967: | #207 complete v2 state transition from
STATE_V2_CREATE_I with STF_OK
124 Jun 15 14:21:21.427038: | child state #207:
STATE_V2_CREATE_I(established-authenticated-ike) =>
STATE_V2_IPSEC_I(authenticated-ipsec)
125 Jun 15 14:21:21.427267: | message ID #207 STATE_V2_IPSEC_I vpn/1x9 pst
#169 st_msgid_nextuse(before=74) 74 st_msgid_lastack 73 st_msgid_lastrecv
4294967295 md is a resonse
126 Jun 15 14:21:21.427287: "vpn/1x9" #207: negotiated connection
[xxx.xxx.xxx.80-xxx.xxx.xxx.95:0-65535 0] ->
[xxx.xxx.xxx.166-xxx.xxx.xxx.166:0-65535 0]
127 Jun 15 14:21:21.427328: "vpn/1x9" #207: STATE_V2_IPSEC_I: IPsec SA
established tunnel mode {ESP=>0xd6c50bde <0xe6368e02
xfrm=AES_CBC_256-HMAC_SHA2_256_128-MODP2048 NATOA=none NATD=none DPD=active}
128 Jun 15 14:21:21.427347: | releasing whack for #207 (sock=-1)
129 Jun 15 14:21:21.427415: | unpending state #169 connection "vpn/1x9"
130 Jun 15 14:21:21.427468: | state #207 requesting to delete non existing
event
131 Jun 15 14:21:21.427512: | inserting event EVENT_SA_REPLACE, timeout in
27961.000 seconds for #207
132 Jun 15 14:21:21.427567: | inserting event EVENT_v2_LIVENESS, timeout in
30.000 seconds for #207
133 Jun 15 14:21:21.427600: | processing: stop state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:597)
134 Jun 15 14:21:24.052941: | serialno table: hash serialno #207 to head
0x563157b99140
135 ...
136 Jun 15 14:21:42.901464: | serialno table: hash serialno #207 to head
0x563157b99140
137 Jun 15 14:21:42.901483: | serialno table: hash serialno #207 to head
0x563157b99140
138 Jun 15 14:21:49.319394: | conn vpn/1x9 mark 0/00000000, 0/00000000
139 Jun 15 14:21:49.320866: | conn vpn/1x9 mark 0/00000000, 0/00000000
140 Jun 15 14:21:51.412791: | handling event EVENT_v2_LIVENESS for child
state #207
141 Jun 15 14:21:51.412815: "vpn/1x9" #207: extra debugging enabled for
connection: none
142 Jun 15 14:21:51.412840: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
143 Jun 15 14:21:51.412861: "vpn/1x9" #207: extra debugging enabled for
connection: none
144 Jun 15 14:21:51.412881: | processing: [RE]START state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in liveness_check() at timer.c:114)
145 Jun 15 14:21:51.412934: | "vpn/1x9" #207 parent connection of this
state is diffeent "vpn/1x18" #169
146 Jun 15 14:21:51.413031: | processing: stop state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:669)
147 Jun 15 14:21:54.052550: | serialno table: hash serialno #207 to head
0x563157b99140
148 Jun 15 14:21:54.052553: | serialno table: hash serialno #207 to head
0x563157b99140
149 Jun 15 14:21:57.971455: | serialno table: hash serialno #207 to head
0x563157b99140
150 Jun 15 14:21:57.971462: | serialno table: hash serialno #207 to head
0x563157b99140
151 Jun 15 14:22:01.054219: | pending review: connection "vpn/1x9" checked
152 Jun 15 14:22:01.369389: | serialno table: hash serialno #207 to head
0x563157b99140
153 ...
154 Jun 15 14:34:31.688150: | serialno table: hash serialno #207 to head
0x563157b99140
155 Jun 15 14:34:31.688153: | serialno table: hash serialno #207 to head
0x563157b99140
156 Jun 15 14:34:37.344591: "vpn/1x9" #207: extra debugging enabled for
connection: none
157 Jun 15 14:34:37.344611: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in for_each_state() at state.c:1742)
158 Jun 15 14:34:37.344709: | processing: stop state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in for_each_state() at state.c:1742)
159 Jun 15 14:34:37.345838: "vpn/1x9" #56: extra debugging enabled for
connection: none
160 Jun 15 14:34:37.345858: | processing: start state #56 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in for_each_state() at state.c:1742)
161 Jun 15 14:34:37.345878: | processing: stop state #56 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in for_each_state() at state.c:1742)
162 Jun 15 14:34:39.052934: | serialno table: hash serialno #207 to head
0x563157b99140
163 Jun 15 14:34:39.052937: | serialno table: hash serialno #207 to head
0x563157b99140
164 Jun 15 14:51:21.641018: | serialno table: hash serialno #207 to head
0x563157b99140
165 ...
166 Jun 15 14:51:24.053702: | serialno table: hash serialno #207 to head
0x563157b99140
167 Jun 15 14:51:24.053706: | serialno table: hash serialno #207 to head
0x563157b99140
168 Jun 15 14:51:27.825965: | serialno list: updated newer object
0x56315882f608 (state #207) entry 0x56315882fdb0 (older 0x56315882a680
newer 0x563158830780)
169 Jun 15 14:51:36.717515: | serialno table: hash serialno #207 to head
0x563157b99140
170 ...
171 Jun 15 14:51:54.052172: | serialno table: hash serialno #207 to head
0x563157b99140
172 Jun 15 14:51:57.935511: | serialno list: updated older object
0x56315882f608 (state #207) entry 0x56315882fdb0 (older 0x56315882a680
newer 0x563158837770)
173 Jun 15 14:52:01.145024: | pending review: connection "vpn/1x9" checked
174 Jun 15 14:52:01.750287: | serialno table: hash serialno #207 to head
0x563157b99140
175 ...
176 Jun 15 14:52:24.052144: | serialno table: hash serialno #207 to head
0x563157b99140
177 Jun 15 14:52:27.863998: | serialno list: updated older object
0x56315882f608 (state #207) entry 0x56315882fdb0 (older 0x56315882a680
newer 0x563158838b10)
178 Jun 15 14:52:27.899533: | serialno list: updated newer object
0x56315882f608 (state #207) entry 0x56315882fdb0 (older 0x56315882d940
newer 0x563158838b10)
179 Jun 15 14:52:36.999286: | serialno table: hash serialno #207 to head
0x563157b99140
180 ...
181 Jun 15 14:52:54.052066: | serialno table: hash serialno #207 to head
0x563157b99140
182 Jun 15 14:52:57.831870: | serialno list: updated older object
0x56315882f608 (state #207) entry 0x56315882fdb0 (older 0x56315882d940
newer 0x563158856e90)
183 Jun 15 14:52:57.861344: | v2 child state object #207 found, in
STATE_V2_IPSEC_I
184 Jun 15 14:52:57.861382: "vpn/1x18" #169: received Delete SA payload:
replace IPSEC State #207 now
185 Jun 15 14:52:57.861401: | state #207 requesting EVENT_SA_REPLACE to be
deleted
186 Jun 15 14:52:57.861458: | inserting event EVENT_SA_REPLACE, timeout in
0.000 seconds for #207
187 Jun 15 14:52:57.862558: | handling event EVENT_SA_REPLACE for child
state #207
188 Jun 15 14:52:57.862576: "vpn/1x9" #207: extra debugging enabled for
connection: none
189 Jun 15 14:52:57.862595: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
190 Jun 15 14:52:57.862613: | EVENT_SA_REPLACE picked newest_ipsec_sa #207
191 Jun 15 14:52:57.862672: | creating state object #227 at 0x56315882a8a8
192 Jun 15 14:52:57.862691: | parent state #227: new =>
STATE_UNDEFINED(ignore)
193 Jun 15 14:52:57.862708: | duplicating state object #169 "vpn/1x18" as
#227 for IPSEC SA
194 Jun 15 14:52:57.862728: | processing: suspend state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_initiate_child_sa() at
ikev2_parent.c:6767)
195 Jun 15 14:52:57.862747: "vpn/1x9" #227: extra debugging enabled for
connection: none
196 Jun 15 14:52:57.862765: | processing: start state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_initiate_child_sa() at
ikev2_parent.c:6767)
197 Jun 15 14:52:57.862783: | serialno table: hash serialno #207 to head
0x563157b99140
198 Jun 15 14:52:57.862801: | serialno table: hash serialno #207 to head
0x563157b99140
199 Jun 15 14:52:57.862819: | child state #227: STATE_UNDEFINED(ignore) =>
STATE_V2_REKEY_CHILD_I0(established-authenticated-ike)
200 Jun 15 14:52:57.863173: | inserting state object #227
201 Jun 15 14:52:57.863192: | serialno list: inserting object
0x56315882a8a8 (state #227) entry 0x56315882b050 into list 0x563157ba4840
(older 0x56315882a680 newer 0x5631588564c0)
202 Jun 15 14:52:57.863211: | serialno list: inserted object
0x56315882a8a8 (state #227) entry 0x56315882b050 (older 0x56315882a680
newer 0x563157ba4840)
203 Jun 15 14:52:57.863248: | serialno table: inserting object
0x56315882a8a8 (state #227) entry 0x56315882b070 into list 0x563157b993c0
(older 0x563157b993c0 newer 0x563157b993c0)
204 Jun 15 14:52:57.863266: | serialno table: inserted object
0x56315882a8a8 (state #227) entry 0x56315882b070 (older 0x563157b993c0
newer 0x563157b993c0)
205 Jun 15 14:52:57.863305: | serialno table: hash serialno #207 to head
0x563157b99140
206 Jun 15 14:52:57.863323: | serialno table: hash serialno #207 to head
0x563157b99140
207 Jun 15 14:52:57.863348: | constructing ESP/AH proposals with default DH
MODP2048 for vpn/1x9 (ESP/AH initiator emitting proposals)
208 Jun 15 14:52:57.863421: "vpn/1x9" #227: local ESP/AH proposals for
vpn/1x9 (ESP/AH initiator emitting proposals):
1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048;ESN=DISABLED
209 Jun 15 14:52:57.863443: | #227 schedule rekey initiate IPsec SA
PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV2_ALLOW+IKEV2_PROPOSE+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
to replace #207 using IKE# 169 pfs=MODP2048
210 Jun 15 14:52:57.863461: | state #227 requesting to delete non existing
event
211 Jun 15 14:52:57.863498: | inserting event EVENT_v2_INITIATE_CHILD,
timeout in 0.000 seconds for #227
212 Jun 15 14:52:57.863519: | processing: RESET state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_initiate_child_sa() at
ikev2_parent.c:6862)
213 Jun 15 14:52:57.863556: | state #207 requesting N/A-pe@(nil) be deleted
214 Jun 15 14:52:57.863590: | state #207 requesting N/A-pe@(nil) be deleted
215 Jun 15 14:52:57.863643: | inserting event EVENT_SA_EXPIRE, timeout in
0.000 seconds for #207
216 Jun 15 14:52:57.863756: | handling event EVENT_v2_INITIATE_CHILD for
child state #227
217 Jun 15 14:52:57.863774: "vpn/1x9" #227: extra debugging enabled for
connection: none
218 Jun 15 14:52:57.863792: | processing: start state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
219 Jun 15 14:52:57.863961: | adding Child Rekey Initiator KE and nonce ni
work-order 347 for state #227
220 Jun 15 14:52:57.863978: | state #227 requesting to delete non existing
event
221 Jun 15 14:52:57.864025: | inserting event EVENT_CRYPTO_TIMEOUT, timeout
in 60.000 seconds for #227
222 Jun 15 14:52:57.864046: | backlog: inserting object 0x563158838368
(work-order 347 state #227) entry 0x563158838370 into list 0x563157ba5740
(older 0x563157ba5740 newer 0x563157ba5740)
223 Jun 15 14:52:57.864065: | backlog: inserted object 0x563158838368
(work-order 347 state #227) entry 0x563158838370 (older 0x563157ba5740
newer 0x563157ba5740)
224 Jun 15 14:52:57.864134: | backlog: removing object 0x563158838368
(work-order 347 state #227) entry 0x563158838370 (older 0x563157ba5740
newer 0x563157ba5740)
225 Jun 15 14:52:57.864171: | crypto helper 1 starting work-order 347 for
state #227
226 Jun 15 14:52:57.865909: | crypto helper 1 sending results from
work-order 347 for state #227 to event queue
227 Jun 15 14:52:57.865929: | scheduling now-event sending helper answer
for #227
228 Jun 15 14:52:57.865999: | processing: stop state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:669)
229 Jun 15 14:52:57.866070: | handling event EVENT_SA_EXPIRE for child
state #207
230 Jun 15 14:52:57.866087: "vpn/1x9" #207: extra debugging enabled for
connection: none
231 Jun 15 14:52:57.866106: | processing: start state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
232 Jun 15 14:52:57.866193: "vpn/1x9" #207: extra debugging enabled for
connection: none
233 Jun 15 14:52:57.866212: | processing: [RE]START state #207 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in delete_state() at state.c:1091)
234 Jun 15 14:52:57.866229: | serialno table: hash serialno #207 to head
0x563157b99140
235 Jun 15 14:52:57.866246: | serialno table: hash serialno #207 to head
0x563157b99140
236 Jun 15 14:52:57.866264: "vpn/1x9" #207: deleting state
(STATE_V2_IPSEC_I) and NOT sending notification
237 Jun 15 14:52:57.866282: | child state #207:
STATE_V2_IPSEC_I(authenticated-ipsec) => delete
238 Jun 15 14:52:57.866358: "vpn/1x9" #207: ESP traffic information: in=0B
out=120B
239 Jun 15 14:52:57.866377: | state #207 requesting N/A-pe@(nil) be deleted
240 Jun 15 14:52:57.866411: | state #207 requesting N/A-pe@(nil) be deleted
241 Jun 15 14:52:57.866445: | state #207 requesting N/A-pe@(nil) be deleted
242 Jun 15 14:52:57.866478: | state #207 requesting N/A-pe@(nil) be deleted
243 Jun 15 14:52:57.866513: | child state #207:
STATE_V2_IPSEC_I(authenticated-ipsec) => STATE_CHILDSA_DEL(informational)
244 Jun 15 14:52:57.866699: | state #207 requesting to delete non existing
event
245 Jun 15 14:52:57.866719: | serialno list: removing object
0x56315882f608 (state #207) entry 0x56315882fdb0 (older 0x56315882d940
newer 0x563158856e90)
246 Jun 15 14:52:57.866777: | serialno table: removing object
0x56315882f608 (state #207) entry 0x56315882fdd0 (older 0x563157b99140
newer 0x563157b99140)
247 Jun 15 14:52:57.867002: | executing down-client:
PLUTO_VERB='down-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='vpn/1x9'
PLUTO_INTERFACE='eth0' PLUTO_NEXT_HOP='xxx.xxx.xxx.81'
PLUTO_ME='xxx.xxx.xxx.92' PLUTO_MY_ID='54.247.44.120'
PLUTO_MY_CLIENT='xxx.xxx.xxx.80/28' PLUT
O_MY_CLIENT_NET='xxx.xxx.xxx.80' PLUTO_MY_CLIENT_MASK='255.255.255.240'
PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_SA_REQID='16420'
PLUTO_SA_TYPE='ESP' PLUTO_PEER='xxx.xxx.xxx.45'
PLUTO_PEER_ID='xxx.xxx.xxx.45' PLUTO_PEER_CLIENT='xxx.xxx.xxx.166/32'
PLUTO_PEER_CLIENT _NET='xxx.xxx.xxx.166'
PLUTO_PEER_CLIENT_MASK='255.255.255.255' PLUTO_PEER_PORT='0'
PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='netkey'
PLUTO_ADDTIME='1623759681'
PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV2_ALLOW+IKEV2_PROPOSE+SAREF_TRACK+IKE_FRAG_ALLOW
+ESN_NO' PLUTO_CONN_KIND='CK_PERMANENT' PLUTO_CONN_ADDRFAMILY='ipv4'
XAUTH_FAILED=0 PLUTO_MY_SOURCEIP='xxx.xxx.xxx.92' PLUTO_IS_PEER_CISCO='0'
PLUTO_PEER_DNS_INFO='' PLUTO_PEER_DOMAIN_INFO='' PLUTO_PEER_BANNER=''
PLUTO_CFG_SERVER='0' PLUTO_CFG_CLIEN
248 Jun 15 14:52:57.867047: | cmd( 0):PLUTO_VERB='down-client'
PLUTO_VERSION='2.0' PLUTO_CONNECTION='vpn/1x9' PLUTO_IN:
249 Jun 15 14:52:57.877772: | shunt_eroute() called for connection
'vpn/1x9' to 'replace with shunt' for rt_kind 'prospective erouted' using
protoports 0--0->-0
250 Jun 15 14:52:57.877848: | priority calculation of connection "vpn/1x9"
is 0xfe3df
251 Jun 15 14:52:57.878093: | priority calculation of connection "vpn/1x9"
is 0xfe3df
252 Jun 15 14:52:57.878354: | in connection_discard for connection vpn/1x9
253 Jun 15 14:52:57.878372: | child state #207:
STATE_CHILDSA_DEL(informational) => STATE_UNDEFINED(ignore)
254 Jun 15 14:52:57.878623: | processing: stop state #207
xxx.xxx.xxx.45:500 (in delete_state() at state.c:1326)
255 Jun 15 14:52:57.878643: | serialno table: hash serialno #207 to head
0x563157b99140
256 Jun 15 14:52:57.878660: | serialno table: hash serialno #207 to head
0x563157b99140
257 Jun 15 14:52:57.880360: | serialno table: hash serialno #227 to head
0x563157b993c0
258 Jun 15 14:52:57.880378: | serialno table: hash serialno #227 to head
0x563157b993c0
259 Jun 15 14:52:57.880397: "vpn/1x9" #227: extra debugging enabled for
connection: none
260 Jun 15 14:52:57.880417: | processing: start state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:594)
261 Jun 15 14:52:57.880469: | ikev2_crypto_continue for #227
262 Jun 15 14:52:57.880527: | #227 send new exchange now using parent #169
unacknowledged 0 next message id=137 ike exchange window 1
263 Jun 15 14:52:57.880546: "vpn/1x9" #227: extra debugging enabled for
connection: none
264 Jun 15 14:52:57.880565: | processing: [RE]START state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in ikev2_child_out_cont() at
ikev2_parent.c:5815)
265 Jun 15 14:52:57.881770: | serialno table: hash serialno #207 to head
0x563157b99140
266 Jun 15 14:52:57.881787: | serialno table: hash serialno #207 to head
0x563157b99140
267 Jun 15 14:52:57.881805: "vpn/1x9" #227: Child SA to rekey #207 vanished
abort this exchange
268 Jun 15 14:52:57.881841: "vpn/1x9" #227: extra debugging enabled for
connection: none
269 Jun 15 14:52:57.881861: | processing: [RE]START state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in complete_v2_state_transition() at
ikev2.c:2787)
270 Jun 15 14:52:57.881880: | #227 complete v2 state transition from
STATE_V2_REKEY_CHILD_I0 with STF_INTERNAL_ERROR
271 Jun 15 14:52:57.882086: | processing: stop state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:597)
272 Jun 15 14:53:57.834975: | serialno list: updated newer object
0x56315882a8a8 (state #227) entry 0x56315882b050 (older 0x563158853870
newer 0x563157ba4840)
273 Jun 15 14:53:57.865909: | handling event EVENT_CRYPTO_TIMEOUT for child
state #227
274 Jun 15 14:53:57.865931: "vpn/1x9" #227: extra debugging enabled for
connection: none
275 Jun 15 14:53:57.865954: | processing: start state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
276 Jun 15 14:53:57.865973: | event crypto_failed on state #227, aborting
277 Jun 15 14:53:57.865992: "vpn/1x9" #227: extra debugging enabled for
connection: none
278 Jun 15 14:53:57.866016: | processing: [RE]START state #227 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in delete_state() at state.c:1091)
279 Jun 15 14:53:57.866036: | serialno table: hash serialno #227 to head
0x563157b993c0
280 Jun 15 14:53:57.866054: | serialno table: hash serialno #227 to head
0x563157b993c0
281 Jun 15 14:53:57.866074: "vpn/1x9" #227: deleting state
(STATE_V2_REKEY_CHILD_I0) and NOT sending notification
282 Jun 15 14:53:57.866236: | child state #227:
STATE_V2_REKEY_CHILD_I0(established-authenticated-ike) => delete
283 Jun 15 14:53:57.866316: | state #227 requesting N/A-pe@(nil) be deleted
284 Jun 15 14:53:57.866392: | state #227 requesting N/A-pe@(nil) be deleted
285 Jun 15 14:53:57.866435: | state #227 requesting N/A-pe@(nil) be deleted
286 Jun 15 14:53:57.866470: | state #227 requesting N/A-pe@(nil) be deleted
287 Jun 15 14:53:57.866508: | child state #227:
STATE_V2_REKEY_CHILD_I0(established-authenticated-ike) =>
STATE_CHILDSA_DEL(informational)
288 Jun 15 14:53:57.866806: | state #227 requesting to delete non existing
event
289 Jun 15 14:53:57.866826: | serialno list: removing object
0x56315882a8a8 (state #227) entry 0x56315882b050 (older 0x563158853870
newer 0x563157ba4840)
290 Jun 15 14:53:57.866884: | serialno table: removing object
0x56315882a8a8 (state #227) entry 0x56315882b070 (older 0x563157b993c0
newer 0x563157b993c0)
291 Jun 15 14:53:57.867013: | priority calculation of connection "vpn/1x9"
is 0xfe3df
292 Jun 15 14:53:57.867095: | in connection_discard for connection vpn/1x9
293 Jun 15 14:53:57.867114: | child state #227:
STATE_CHILDSA_DEL(informational) => STATE_UNDEFINED(ignore)
294 Jun 15 14:53:57.867344: | processing: stop state #227
xxx.xxx.xxx.45:500 (in delete_state() at state.c:1326)
295 Jun 15 14:53:57.867365: | serialno table: hash serialno #227 to head
0x563157b993c0
296 Jun 15 14:53:57.867388: | serialno table: hash serialno #227 to head
0x563157b993c0
297 Jun 15 14:54:01.148212: | pending review: connection "vpn/1x9" checked
298 ...
299 Jun 15 15:02:01.169529: | pending review: connection "vpn/1x9" checked
300 Jun 15 15:03:36.458433: "vpn/1x9" #56: extra debugging enabled for
connection: none
301 Jun 15 15:03:36.458452: | processing: start state #56 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in for_each_state() at state.c:1742)
302 Jun 15 15:03:36.458472: | processing: stop state #56 connection
"vpn/1x9" xxx.xxx.xxx.45:500 (in for_each_state() at state.c:1742)
303 Jun 15 15:04:01.178346: | pending review: connection "vpn/1x9" checked
304 ...
305 Jun 15 15:14:01.199914: | pending review: connection "vpn/1x9" checked
306 Jun 15 15:15:42.776002: | investigating connection "vpn/1x9" as a
better match
307 Jun 15 15:15:42.776020: | ikev2_evaluate_connection_fit evaluating
our conn="vpn/1x9" I=xxx.xxx.xxx.166/32:0/0 R=xxx.xxx.xxx.80/28:0/0 to
their:
308 Jun 15 15:15:42.776110: | prefix fitness rejected d vpn/1x9
309 Jun 15 15:15:42.788257: | conn vpn/1x9 mark 0/00000000, 0/00000000
310 Jun 15 15:15:42.789686: | conn vpn/1x9 mark 0/00000000, 0/00000000
311 Jun 15 15:16:01.206342: | pending review: connection "vpn/1x9" checked
312 Jun 15 15:18:01.208991: | pending review: connection "vpn/1x9" checked
Also I could notice too checking the Libreswan FAQ that there are some data
here that I don't know how to manage, even after read this (
https://www.kernel.org/doc/Documentation/networking/xfrm_proc.txt):
cat /proc/net/xfrm_stat
XfrmInError 0
XfrmInBufferError 0
XfrmInHdrError 0
XfrmInNoStates 1
XfrmInStateProtoError 0
XfrmInStateModeError 0
XfrmInStateSeqError 0
XfrmInStateExpired 0
XfrmInStateMismatch 0
XfrmInStateInvalid 0
XfrmInTmplMismatch 0
XfrmInNoPols 5294
XfrmInPolBlock 0
XfrmInPolError 0
XfrmOutError 0
XfrmOutBundleGenError 0
XfrmOutBundleCheckError 0
XfrmOutNoStates 33461
XfrmOutStateProtoError 0
XfrmOutStateModeError 2
XfrmOutStateSeqError 0
XfrmOutStateExpired 0
XfrmOutPolBlock 0
XfrmOutPolDead 0
XfrmOutPolError 0
XfrmFwdHdrError 0
XfrmOutStateInvalid 0
XfrmAcquireError 1
Thanks in advance,
Best regards!
Miguel Ponce Antolín
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20210615/5cb5d75d/attachment-0001.html>
More information about the Swan
mailing list