[Swan] Fwd: Problem with random rekey failures

Miguel Ponce Antolin mponce at paradigmadigital.com
Tue Jun 15 09:54:30 UTC 2021


Hi everyone,

I have been suffering a random problem with libreswan v3.25 when connecting
an AWS EC2 Instance running Libreswan and a Cisco ASA on the other end.

The phase 1 ISAKMP is renegotiated and successfully reestablished while is
associated with a concrete rightsubnet, specifically with the last one
vpn/1x18. We have configured 18 rightsubnets.

The problem comes when the phase 2 is renewed. Sometimes, in a complete
random way, AWS EC2 Libreswan side cannot restart rightsubnets with a
connection event (ping, netcat, telnet). Let me explain more details:
- First, in my ipsec.d config it is configured ikelifetime=28800s and
salifetime=28800s, but the phase 2 of every connection goes down after 30
minutes without traffic flow.
- When the problem is active. If any phase 2 is down I can reconnect it,
ALWAYS, from the Cisco ASA side to the AWS EC2 side by sending some
traffic, but *it is not possible to reconnect any subnet from AWS to the
Cisco ASA side*.
- The only solution to this problem is to stop and restart the IPsec
service. After the restart when a connection is Down we can reestablish it
by sending some traffic from both sides.
- For some reason this state happens randomly, we have been testing a long
time this problem and we can be working without this issue for 10 days. But
since last Wednesday it is happening, at least, once a day.


*Troubleshooting done:*

- Checked firewall on both sides

- Iptables is disabled an systemd masked on the AWS EC2 Libreswan side

- Selinux is disabled on the AWS EC2 Libreswan side

- Subnets configuration are the same in the same order on both sides

- Routes on both sides are checked, actually they are working well when the
problem is not active.

- Sysctl.conf:

net.ipv4.conf.all.rp_filter = 0
net.ipv4.conf.default.rp_filter = 0
net.ipv4.conf.eth0.rp_filter = 0
net.ipv4.conf.ip_vti0.rp_filter = 0
net.ipv4.conf.all.accept_redirects = 0
net.ipv4.conf.all.send_redirects = 0
net.ipv4.conf.default.send_redirects = 0
net.ipv4.conf.eth0.send_redirects = 0
net.ipv4.conf.default.accept_redirects = 0
net.ipv4.conf.eth0.accept_redirects = 0
net.ipv4.tcp_app_win=1380
net.ipv4.ip_forward=1

- These are the* IPsec configuration files* (the "subnet.n" string is
replacing the subnet numbers, but they are correctly set):

*/etc/ipsec.conf*

# /etc/ipsec.conf - Libreswan IPsec configuration file

config setup

plutodebug="all crypt"
plutostderrlog=/var/log/libreswan.log
#
virtual_private=%v4:10.subnet.1.0/22,%v4:10.subnet.2.0/20,%v4:10.subnet.3.128/25,%v4:10.subnet.4.74/32,%v4:10.subnet.5.75/32,%v4:10..subnet.6.224/27,%v4:10.subnet.7.0/24,%v4:10.subnet.8.200/31,%v4:10.subnet.9.166/32,%v4:10.subnet.10.0/16,%v4:11.subnet.11.0/24,%v4:10.subnet.12.0/24,%v4:10.subnet.13.16/28,%v4:10.subnet.14.16/28,%v4:10.subnet.15.128/26,%v4:10.subnet.16.17/32,%v4:10.subnet.17.0/24,%v4:10.subnet.18.9/32

*/etc/ipsec.d/vpn.conf*

conn vpn
    type=tunnel
    authby=secret
    auto=start
    left=%defaultroute
    leftid=xxx.xxx.xxx.120
    leftsubnets=xxx.xxx.xxx.80/28
    right=xxx.xxx.xxx.45
    rightid=xxx.xxx.xxx.45
    rightsubnets={10.subnet.1.0/22 10.subnet.2.0/20 10.subnet.3.128/25
10.subnet.4.74/32 10.subnet.5.75/32 10.subnet.6.224/27 10.subnet.7.0/24
10.subnet.8.200/31 10.subnet.9.166/32 10.subnet.10.0/16 10.subnet.11.0/24
10.subnet.12.16/28 10.subnet.13.16/28 10.subnet.14.128/26
10.subnet.15.17/32 10.subnet.16.0/24 10.subnet.17.0/24 10.subnet.18.9/32}
    leftsourceip=xxx.xxx.xxx.92
    ikev2=insist
    ike=aes256-sha2;dh14
    esp=aes256-sha256
    keyexchange=ike
    ikelifetime=28800s
    salifetime=28800s
    dpddelay=30
    dpdtimeout=120
    dpdaction=restart
    encapsulation=no


We are testing libreswan in the staging environment but we want to promote
it to the production environment.

We tried to "force" to reconnect using the ping command to an IP in various
rightsubnets but when the problem is active we continously are seeing this
kind of logs:

 Jun 11 11:17:25.795041: | crypto helper 1 finished build KE and nonce;
request ID 315 time elapsed 1762 usec
Jun 11 11:17:25.795049: | crypto helper 1 sending results from work-order
315 for state #221 to event queue
Jun 11 11:17:25.795054: | scheduling now-event sending helper answer for
#221
Jun 11 11:17:25.795061: | crypto helper 1 waiting (nothing to do)
Jun 11 11:17:25.795073: | free_event_entry: release
EVENT_v2_INITIATE_CHILD-pe at 0x56205dce1a88
Jun 11 11:17:25.795079: | processing: stop state #221 connection "vpn/1x15"
xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:669)
Jun 11 11:17:25.795083: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:25.795086: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:25.795097: | executing now-event sending helper answer for 221
Jun 11 11:17:25.795100: | serialno table: hash serialno #221 to head
0x56205ca82300
Jun 11 11:17:25.795103: | serialno table: hash serialno #221 to head
0x56205ca82300
Jun 11 11:17:25.795108: | processing: start state #221 connection
"vpn/1x15" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:594)
Jun 11 11:17:25.795111: | crypto helper 1 replies to request ID 315
Jun 11 11:17:25.795114: | calling continuation function 0x56205c79f9f0
Jun 11 11:17:25.795117: | ikev2_crypto_continue for #221
Jun 11 11:17:25.795120: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:25.795123: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:25.795130: | wire (crypto helper) group MODP2048 and state
group MODP2048 match
Jun 11 11:17:25.795134: | DH secret MODP2048 at 0x7f3d9004a728: transferring
ownership from helper KE to state #221
Jun 11 11:17:25.795137: | state #221 requesting EVENT_CRYPTO_TIMEOUT to be
deleted
Jun 11 11:17:25.795141: | free_event_entry: release
EVENT_CRYPTO_TIMEOUT-pe at 0x56205dce1a18
Jun 11 11:17:25.795144: | event_schedule: new
EVENT_SA_REPLACE-pe at 0x56205dce1a18
Jun 11 11:17:25.795149: | inserting event EVENT_SA_REPLACE, timeout in
200.000 seconds for #221
Jun 11 11:17:25.795153: "vpn/1x15" #221: message id deadlock? wait sending,
add to send next list using parent #165 unacknowledged 1 next message id=63
ike exchange window 1
Jun 11 11:17:25.795160: | #221 wait sending, add to send next list using
parent #165 unacknowledged 1 next message id=63 ike exchange window 1
Jun 11 11:17:25.795164: | suspending state #221 and saving MD
Jun 11 11:17:25.795167: | #221 is busy; has a suspended MD
Jun 11 11:17:25.795172: | processing: [RE]START state #221 connection
"vpn/1x15" xxx.xxx.xxx.45:500 (in log_stf_suspend() at ikev2.c:2691)
Jun 11 11:17:25.795176: | "vpn/1x15" #221 complete v2 state
STATE_V2_CREATE_I0 transition with STF_SUSPEND suspended from
complete_v2_state_transition:2763
Jun 11 11:17:25.795180: | processing: stop state #221 connection "vpn/1x15"
xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:597)
Jun 11 11:17:25.795183: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:25.795186: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:27.919414: | timer_event_cb: processing event at 0x56205dcd6cc8
Jun 11 11:17:27.919448: | handling event EVENT_SHUNT_SCAN
Jun 11 11:17:27.919458: | expiring aged bare shunts from shunt table
Jun 11 11:17:27.919464: | event_schedule: new
EVENT_SHUNT_SCAN-pe at 0x56205dce1a88
Jun 11 11:17:27.919469: | inserting event EVENT_SHUNT_SCAN, timeout in
20.000 seconds
Jun 11 11:17:27.919477: | free_event_entry: release
EVENT_SHUNT_SCAN-pe at 0x56205dcd6cc8
Jun 11 11:17:34.935626: | timer_event_cb: processing event at 0x56205dcca398
Jun 11 11:17:34.935666: | handling event EVENT_SA_REPLACE for child state
#218
Jun 11 11:17:34.935676: | processing: start state #218 connection
"vpn/1x11" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
Jun 11 11:17:34.935681: | EVENT_SA_REPLACE picked newest_ipsec_sa #0
Jun 11 11:17:34.935686: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:34.935689: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:34.935698: | connection vpn/1x11 has 1 pending IPsec
negotiations ike #165 last child state #218
Jun 11 11:17:34.935711: | state #218 requesting N/A-pe@(nil) be deleted
Jun 11 11:17:34.935715: | delete_pluto_event cannot delete NULL event
Jun 11 11:17:34.935718: | state #218 requesting N/A-pe@(nil) be deleted
Jun 11 11:17:34.935720: | delete_pluto_event cannot delete NULL event
Jun 11 11:17:34.935725: | event_schedule: new
EVENT_SA_EXPIRE-pe at 0x56205dcd6cc8
Jun 11 11:17:34.935731: | inserting event EVENT_SA_EXPIRE, timeout in 0.000
seconds for #218
Jun 11 11:17:34.935740: | free_event_entry: release
EVENT_SA_REPLACE-pe at 0x56205dcca398
Jun 11 11:17:34.935745: | processing: stop state #218 connection "vpn/1x11"
xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:669)
Jun 11 11:17:34.935748: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:34.935751: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:34.935759: | timer_event_cb: processing event at 0x56205dcd6cc8
Jun 11 11:17:34.935762: | handling event EVENT_SA_EXPIRE for child state
#218
Jun 11 11:17:34.935766: | processing: start state #218 connection
"vpn/1x11" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
Jun 11 11:17:34.935769: | EVENT_SA_EXPIRE picked newest_ipsec_sa
Jun 11 11:17:34.935772: | un-established partial ISAKMP SA timeout (SA
expired)
Jun 11 11:17:34.935775: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:34.935778: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:34.935783: | processing: [RE]START state #218 connection
"vpn/1x11" xxx.xxx.xxx.45:500 (in delete_state() at state.c:1091)
Jun 11 11:17:34.935786: | serialno table: hash serialno #218 to head
0x56205ca822a0
Jun 11 11:17:34.935789: | serialno table: hash serialno #218 to head
0x56205ca822a0
Jun 11 11:17:34.935794: "vpn/1x11" #218: deleting state
(STATE_V2_CREATE_I0) and NOT sending notification
Jun 11 11:17:34.935798: | child state #218:
STATE_V2_CREATE_I0(established-authenticated-ike) => delete
Jun 11 11:17:34.935801: | state #218 requesting N/A-pe@(nil) be deleted
Jun 11 11:17:34.935804: | delete_pluto_event cannot delete NULL event
Jun 11 11:17:34.935807: | state #218 requesting N/A-pe@(nil) be deleted
Jun 11 11:17:34.935809: | delete_pluto_event cannot delete NULL event
Jun 11 11:17:34.935812: | state #218 requesting N/A-pe@(nil) be deleted
Jun 11 11:17:34.935815: | delete_pluto_event cannot delete NULL event
Jun 11 11:17:34.935818: | state #218 requesting N/A-pe@(nil) be deleted
Jun 11 11:17:34.935821: | delete_pluto_event cannot delete NULL event
Jun 11 11:17:34.935824: | disconnecting state #218 from md
Jun 11 11:17:34.935829: | child state #218:
STATE_V2_CREATE_I0(established-authenticated-ike) =>
STATE_CHILDSA_DEL(informational)
Jun 11 11:17:34.935832: | ignore states: 0

Or this one:

Jun 11 11:17:02.313836: | find_connection: conn "vpn/1x12" has compatible
peers: xxx.xxx.xxx.80/28 -> xxx.xxx.xxx.16/28 [pri: 29417482]
Jun 11 11:17:02.313839: | find_connection: first OK "vpn/1x12"
[pri:29417482]{0x56205dc968b8} (child none)
Jun 11 11:17:02.313844: | find_connection: concluding with "vpn/1x12"
[pri:29417482]{0x56205dc968b8} kind=CK_PERMANENT
Jun 11 11:17:02.313848: | assign hold, routing was prospective erouted,
needs to be erouted HOLD
Jun 11 11:17:02.313851: | assign_holdpass() need broad(er) shunt
Jun 11 11:17:02.313854: | priority calculation of connection "vpn/1x12" is
0xfe3e3
Jun 11 11:17:02.313859: | eroute_connection replace %trap with broad %pass
or %hold eroute xxx.xxx.xxx.80/28:0 --0-> xxx.xxx.xxx.16/28:0 =>
%hold>%hold (raw_eroute)
Jun 11 11:17:02.313863: | netlink_raw_eroute: SPI_HOLD implemented as no-op
Jun 11 11:17:02.313867: | raw_eroute result=success
Jun 11 11:17:02.313870: | assign_holdpass() eroute_connection() done
Jun 11 11:17:02.313873: | fiddle_bare_shunt called
Jun 11 11:17:02.313876: | fiddle_bare_shunt with transport_proto 1
Jun 11 11:17:02.313879: | removing specific host-to-host bare shunt
Jun 11 11:17:02.313883: | delete narrow %hold eroute xxx.xxx.xxx.94/32:8
--1-> xxx.xxx.xxx.22/32:0 => %hold (raw_eroute)
Jun 11 11:17:02.313886: | netlink_raw_eroute: SPI_PASS
Jun 11 11:17:02.313895: | raw_eroute result=success
Jun 11 11:17:02.313899: | raw_eroute with op='delete' for
transport_proto='1' kernel shunt succeeded, bare shunt lookup succeeded
Jun 11 11:17:02.313903: | delete bare shunt 0x56205dbeada8
xxx.xxx.xxx.94/32:8 --1--> xxx.xxx.xxx.22/32:0 => %hold 0
 %acquire-netlink
Jun 11 11:17:02.313906: assign_holdpass() delete_bare_shunt() failed
Jun 11 11:17:02.313909: initiate_ondemand_body() failed to install
negotiation_shunt,
Jun 11 11:17:02.313916: | creating state object #219 at 0x56205dcc92c8
Jun 11 11:17:02.313920: | parent state #219: new => STATE_UNDEFINED(ignore)
Jun 11 11:17:02.313923: | duplicating state object #165 "vpn/1x18" as #219
for IPSEC SA
Jun 11 11:17:02.313931: | processing: start state #219 connection
"vpn/1x12" xxx.xxx.xxx.45:500 (in ikev2_initiate_child_sa() at
ikev2_parent.c:6767)
Jun 11 11:17:02.313935: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:02.313938: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:02.313942: | child state #219: STATE_UNDEFINED(ignore) =>
STATE_V2_CREATE_I0(established-authenticated-ike)
Jun 11 11:17:02.313944: | ignore states: 0
Jun 11 11:17:02.313947: | half-open-ike states: 0
Jun 11 11:17:02.313950: | open-ike states: 0
Jun 11 11:17:02.313953: | established-anonymous-ike states: 0
Jun 11 11:17:02.313956: | established-authenticated-ike states: 7
Jun 11 11:17:02.313959: | anonymous-ipsec states: 0
Jun 11 11:17:02.313962: | authenticated-ipsec states: 4
Jun 11 11:17:02.313964: | informational states: 0
Jun 11 11:17:02.313967: | unknown states: 0
Jun 11 11:17:02.313970: | category states: 11 count states: 11
Jun 11 11:17:02.313973: | inserting state object #219
Jun 11 11:17:02.313978: | serialno list: inserting object 0x56205dcc92c8
(state #219) entry 0x56205dcc9a70 into list 0x56205ca8d840 (older
0x56205dcdfb10 newer 0x56205dcb89f0)
Jun 11 11:17:02.313982: | serialno list: inserted  object 0x56205dcc92c8
(state #219) entry 0x56205dcc9a70 (older 0x56205dcdfb10 newer
0x56205ca8d840)
Jun 11 11:17:02.313986: | serialno list: list entry 0x56205ca8d840 is HEAD
(older 0x56205dcc9a70 newer 0x56205dcb89f0)
Jun 11 11:17:02.313990: | serialno table: inserting object 0x56205dcc92c8
(state #219) entry 0x56205dcc9a90 into list 0x56205ca822c0 (older
0x56205ca822c0 newer 0x56205ca822c0)
Jun 11 11:17:02.313994: | serialno table: inserted  object 0x56205dcc92c8
(state #219) entry 0x56205dcc9a90 (older 0x56205ca822c0 newer
0x56205ca822c0)
Jun 11 11:17:02.313999: | serialno table: list entry 0x56205ca822c0 is HEAD
(older 0x56205dcc9a90 newer 0x56205dcc9a90)
Jun 11 11:17:02.314003: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:02.314006: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:02.314015: | constructing ESP/AH proposals with default DH
MODP2048  for vpn/1x12 (ESP/AH initiator emitting proposals)
Jun 11 11:17:02.314020: | converting proposal AES_CBC_256-HMAC_SHA2_256_128
to ikev2 ...
Jun 11 11:17:02.314027: | ...  ikev2_proposal:
1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048;ESN=DISABLED
Jun 11 11:17:02.314032: "vpn/1x12" #219: local ESP/AH proposals for
vpn/1x12 (ESP/AH initiator emitting proposals):
1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048;ESN=DISABLED
Jun 11 11:17:02.314036: | DH ike_alg_lookup_by_id id: MODP2048=14, found
MODP2048
Jun 11 11:17:02.314041: | #219 schedule initiate IPsec SA
PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV2_ALLOW+IKEV2_PROPOSE+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
using IKE# 165 pfs=MODP2048
Jun 11 11:17:02.314044: | state #219 requesting to delete non existing event
Jun 11 11:17:02.314048: | event_schedule: new
EVENT_v2_INITIATE_CHILD-pe at 0x56205dcd6cc8
Jun 11 11:17:02.314053: | inserting event EVENT_v2_INITIATE_CHILD, timeout
in 0.000 seconds for #219
Jun 11 11:17:02.314059: | processing: RESET state #219 connection
"vpn/1x12" xxx.xxx.xxx.45:500 (in ikev2_initiate_child_sa() at
ikev2_parent.c:6862)
Jun 11 11:17:02.314063: | initiate on demand using RSASIG from
xxx.xxx.xxx.94 to xxx.xxx.xxx.22
Jun 11 11:17:02.314072: | timer_event_cb: processing event at 0x56205dcd6cc8
Jun 11 11:17:02.314075: | handling event EVENT_v2_INITIATE_CHILD for child
state #219
Jun 11 11:17:02.314080: | processing: start state #219 connection
"vpn/1x12" xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:319)
Jun 11 11:17:02.314083: | Calling ikev2_crypto_start() from
ikev2_child_outI in state STATE_V2_CREATE_I0
Jun 11 11:17:02.314087: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:02.314090: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:02.314095: | adding Child Initiator KE and nonce ni work-order
313 for state #219
Jun 11 11:17:02.314098: | state #219 requesting to delete non existing event
Jun 11 11:17:02.314102: | event_schedule: new
EVENT_CRYPTO_TIMEOUT-pe at 0x56205dcb8108
Jun 11 11:17:02.314106: | inserting event EVENT_CRYPTO_TIMEOUT, timeout in
60.000 seconds for #219
Jun 11 11:17:02.314111: | backlog: inserting object 0x56205dcc18a8
(work-order 313 state #219) entry 0x56205dcc18b0 into list 0x56205ca8e740
(older 0x56205ca8e740 newer 0x56205ca8e740)
Jun 11 11:17:02.314115: | backlog: inserted  object 0x56205dcc18a8
(work-order 313 state #219) entry 0x56205dcc18b0 (older 0x56205ca8e740
newer 0x56205ca8e740)
Jun 11 11:17:02.314118: | backlog: list entry 0x56205ca8e740 is HEAD (older
0x56205dcc18b0 newer 0x56205dcc18b0)
Jun 11 11:17:02.314135: | crypto helper 1 resuming
Jun 11 11:17:02.314140: | backlog: removing  object 0x56205dcc18a8
(work-order 313 state #219) entry 0x56205dcc18b0 (older 0x56205ca8e740
newer 0x56205ca8e740)
Jun 11 11:17:02.314143: | backlog: empty
Jun 11 11:17:02.314147: | crypto helper 1 starting work-order 313 for state
#219
Jun 11 11:17:02.314151: | crypto helper 1 doing build KE and nonce; request
ID 313
Jun 11 11:17:02.314166: | NSS: Value of Prime:
...
Jun 11 11:17:02.315908: | crypto helper 1 finished build KE and nonce;
request ID 313 time elapsed 1758 usec

Jun 11 11:17:02.315912: | crypto helper 1 sending results from work-order
313 for state #219 to event queue
Jun 11 11:17:02.315915: | scheduling now-event sending helper answer for
#219
Jun 11 11:17:02.315921: | crypto helper 1 waiting (nothing to do)
Jun 11 11:17:02.315930: | free_event_entry: release
EVENT_v2_INITIATE_CHILD-pe at 0x56205dcd6cc8
Jun 11 11:17:02.315936: | processing: stop state #219 connection "vpn/1x12"
xxx.xxx.xxx.45:500 (in timer_event_cb() at timer.c:669)
Jun 11 11:17:02.315939: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:02.315942: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:02.315952: | executing now-event sending helper answer for 219
Jun 11 11:17:02.315955: | serialno table: hash serialno #219 to head
0x56205ca822c0
Jun 11 11:17:02.315958: | serialno table: hash serialno #219 to head
0x56205ca822c0
Jun 11 11:17:02.315962: | processing: start state #219 connection
"vpn/1x12" xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:594)
Jun 11 11:17:02.315966: | crypto helper 1 replies to request ID 313
Jun 11 11:17:02.315968: | calling continuation function 0x56205c79f9f0
Jun 11 11:17:02.315972: | ikev2_crypto_continue for #219
Jun 11 11:17:02.315975: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:02.315978: | serialno table: hash serialno #165 to head
0x56205ca81c00
Jun 11 11:17:02.315982: | wire (crypto helper) group MODP2048 and state
group MODP2048 match
Jun 11 11:17:02.315986: | DH secret MODP2048 at 0x7f3d90045288: transferring
ownership from helper KE to state #219
Jun 11 11:17:02.315990: | state #219 requesting EVENT_CRYPTO_TIMEOUT to be
deleted
Jun 11 11:17:02.315998: | free_event_entry: release
EVENT_CRYPTO_TIMEOUT-pe at 0x56205dcb8108
Jun 11 11:17:02.316001: | event_schedule: new
EVENT_SA_REPLACE-pe at 0x56205dcb8108
Jun 11 11:17:02.316005: | inserting event EVENT_SA_REPLACE, timeout in
200.000 seconds for #219
Jun 11 11:17:02.316010: "vpn/1x12" #219: message id deadlock? wait sending,
add to send next list using parent #165 unacknowledged 1 next message id=63
ike exchange window 1
Jun 11 11:17:02.316017: | #219 wait sending, add to send next list using
parent #165 unacknowledged 1 next message id=63 ike exchange window 1
Jun 11 11:17:02.316020: | suspending state #219 and saving MD
Jun 11 11:17:02.316023: | #219 is busy; has a suspended MD
Jun 11 11:17:02.316028: | processing: [RE]START state #219 connection
"vpn/1x12" xxx.xxx.xxx.45:500 (in log_stf_suspend() at ikev2.c:2691)
Jun 11 11:17:02.316032: | "vpn/1x12" #219 complete v2 state
STATE_V2_CREATE_I0 transition with STF_SUSPEND suspended from
complete_v2_state_transition:2763
Jun 11 11:17:02.316036: | processing: stop state #219 connection "vpn/1x12"
xxx.xxx.xxx.45:500 (in schedule_event_now_cb() at server.c:597)
Jun 11 11:17:02.316039: | serialno table: hash serialno #0 to head
0x56205ca80760
Jun 11 11:17:02.316042: | serialno table: hash serialno #0 to head
0x56205ca80760


Could you please help us with some possible cause we are missing here?
Is there any troubleshooting we could do in order to know where the rekey
request is lost or why is not trying to rekey at all when this problem is
active?

Thanks in advance,

Best regards!

-- 

[image: Logo Especialidad]

*Miguel Ponce Antolín.*
Sistemas    ·    +34 670 360 655
[image: Linea]
[image: Logo Paradigma]   ·   paradig.ma <https://www.paradigmadigital.com/>
·   contáctanos <https://www.paradigmadigital.com/contacto>   ·   [image:
Twitter] <https://twitter.com/paradigmate>  [image: Youtube]
<https://www.youtube.com/user/ParadigmaTe?feature=watch>  [image: Linkedin]
<https://www.linkedin.com/company/paradigma-digital/>  [image: Instagram]
<https://www.instagram.com/paradigma_digital/?hl=es>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20210615/f77065d1/attachment-0001.html>


More information about the Swan mailing list