<div dir="ltr"><div class="gmail_default" style="font-family:verdana,sans-serif;color:#073763">Hi everyone,<br></div><div class="gmail_quote"><div dir="ltr"><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">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.</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">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.</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">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:</div><div style="font-family:verdana,sans-serif;color:#073763">- 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.</div><div style="font-family:verdana,sans-serif;color:#073763">- 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 <b>it is not possible to reconnect any subnet from AWS to the Cisco ASA side</b>.</div><div style="font-family:verdana,sans-serif;color:#073763">- 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.</div><div style="font-family:verdana,sans-serif;color:#073763">- 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.</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763"><b>Troubleshooting done:<br></b></div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">- Checked firewall on both sides</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">- Iptables is disabled an systemd masked on the AWS EC2 Libreswan side</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">- Selinux is disabled on the AWS EC2 Libreswan side</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">- Subnets configuration are the same in the same order on both sides</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">- Routes on both sides are checked, actually they are working well when the problem is not active.</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">- Sysctl.conf:</div><div style="color:rgb(7,55,99)"><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div style="color:rgb(7,55,99)"><font face="monospace">net.ipv4.conf.all.rp_filter = 0<br>net.ipv4.conf.default.rp_filter = 0<br>net.ipv4.conf.eth0.rp_filter = 0<br>net.ipv4.conf.ip_vti0.rp_filter = 0<br>net.ipv4.conf.all.accept_redirects = 0<br>net.ipv4.conf.all.send_redirects = 0<br>net.ipv4.conf.default.send_redirects = 0<br>net.ipv4.conf.eth0.send_redirects = 0<br>net.ipv4.conf.default.accept_redirects = 0<br>net.ipv4.conf.eth0.accept_redirects = 0<br></font></div><div style="color:rgb(7,55,99)"><font face="monospace">net.ipv4.tcp_app_win=1380<br>net.ipv4.ip_forward=1</font><br></div><div style="font-family:verdana,sans-serif;color:rgb(7,55,99)"><br></div></blockquote></div><div style="font-family:verdana,sans-serif;color:#073763">- These are the<b> IPsec configuration files</b> (the "subnet.n" string is replacing the subnet numbers, but they are correctly set):</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763"><b>/etc/ipsec.conf</b></div><div style="color:rgb(7,55,99)"><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div style="color:rgb(7,55,99)"><font face="monospace"># /etc/ipsec.conf - Libreswan IPsec configuration file<br><br>config setup<br><br> plutodebug="all crypt"<br>plutostderrlog=/var/log/libreswan.log<br> # 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<br><br></font></div></blockquote></div><div style="font-family:verdana,sans-serif;color:#073763"><b>/etc/ipsec.d/vpn.conf</b></div><div style="color:rgb(7,55,99)"><blockquote style="margin:0px 0px 0px 40px;border:none;padding:0px"><div style="color:rgb(7,55,99)"><font face="monospace">conn vpn<br> type=tunnel<br> authby=secret<br> auto=start<br> left=%defaultroute<br> leftid=xxx.xxx.xxx.120<br> leftsubnets=xxx.xxx.xxx.80/28<br> right=xxx.xxx.xxx.45<br> rightid=</font>xxx.xxx.xxx.45<font face="monospace"><br> 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}<br> leftsourceip=xxx.xxx.xxx.92<br> ikev2=insist<br> ike=aes256-sha2;dh14<br> esp=aes256-sha256<br> keyexchange=ike<br> ikelifetime=28800s<br> salifetime=28800s<br> dpddelay=30<br> dpdtimeout=120<br> dpdaction=restart<br> encapsulation=no</font><br></div></blockquote></div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">We are testing libreswan in the staging environment but we want to promote it to the production environment.</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">We tried to "force" to reconnect using the ping command to an IP in various rightsubnets<span class="gmail_default" style="font-family:verdana,sans-serif;color:rgb(7,55,99)"> but when the problem is active we continously are seeing this kind of logs:</span></div><div style="font-family:verdana,sans-serif;color:#073763"><br></div></div></div><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div class="gmail_quote"><div dir="ltr"><div style="color:rgb(7,55,99)"><font face="monospace"> <span style="color:rgb(34,34,34)">Jun 11 11:17:25.795041: | crypto helper 1 finished build KE and nonce; request ID 315 time elapsed 1762 usec</span></font></div><font face="monospace">Jun 11 11:17:25.795049: | crypto helper 1 sending results from work-order 315 for state #221 to event queue<br>Jun 11 11:17:25.795054: | scheduling now-event sending helper answer for #221<br>Jun 11 11:17:25.795061: | crypto helper 1 waiting (nothing to do)<br>Jun 11 11:17:25.795073: | free_event_entry: release EVENT_v2_INITIATE_CHILD-pe@0x56205dce1a88<br>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)<br>Jun 11 11:17:25.795083: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:25.795086: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:25.795097: | executing now-event sending helper answer for 221<br>Jun 11 11:17:25.795100: | serialno table: hash serialno #221 to head 0x56205ca82300<br>Jun 11 11:17:25.795103: | serialno table: hash serialno #221 to head 0x56205ca82300<br>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)<br>Jun 11 11:17:25.795111: | crypto helper 1 replies to request ID 315<br>Jun 11 11:17:25.795114: | calling continuation function 0x56205c79f9f0<br>Jun 11 11:17:25.795117: | ikev2_crypto_continue for #221<br>Jun 11 11:17:25.795120: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:25.795123: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:25.795130: | wire (crypto helper) group MODP2048 and state group MODP2048 match<br>Jun 11 11:17:25.795134: | DH secret MODP2048@0x7f3d9004a728: transferring ownership from helper KE to state #221<br>Jun 11 11:17:25.795137: | state #221 requesting EVENT_CRYPTO_TIMEOUT to be deleted<br>Jun 11 11:17:25.795141: | free_event_entry: release EVENT_CRYPTO_TIMEOUT-pe@0x56205dce1a18<br>Jun 11 11:17:25.795144: | event_schedule: new EVENT_SA_REPLACE-pe@0x56205dce1a18<br>Jun 11 11:17:25.795149: | inserting event EVENT_SA_REPLACE, timeout in 200.000 seconds for #221<br>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<br>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<br>Jun 11 11:17:25.795164: | suspending state #221 and saving MD<br>Jun 11 11:17:25.795167: | #221 is busy; has a suspended MD<br>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)<br>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<br>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)<br>Jun 11 11:17:25.795183: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:25.795186: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:27.919414: | timer_event_cb: processing event@0x56205dcd6cc8<br>Jun 11 11:17:27.919448: | handling event EVENT_SHUNT_SCAN<br>Jun 11 11:17:27.919458: | expiring aged bare shunts from shunt table<br>Jun 11 11:17:27.919464: | event_schedule: new EVENT_SHUNT_SCAN-pe@0x56205dce1a88<br>Jun 11 11:17:27.919469: | inserting event EVENT_SHUNT_SCAN, timeout in 20.000 seconds<br>Jun 11 11:17:27.919477: | free_event_entry: release EVENT_SHUNT_SCAN-pe@0x56205dcd6cc8<br>Jun 11 11:17:34.935626: | timer_event_cb: processing event@0x56205dcca398<br>Jun 11 11:17:34.935666: | handling event EVENT_SA_REPLACE for child state #218<br>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)<br>Jun 11 11:17:34.935681: | EVENT_SA_REPLACE picked newest_ipsec_sa #0<br>Jun 11 11:17:34.935686: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:34.935689: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:34.935698: | connection vpn/1x11 has 1 pending IPsec negotiations ike #165 last child state #218<br>Jun 11 11:17:34.935711: | state #218 requesting N/A-pe@(nil) be deleted<br>Jun 11 11:17:34.935715: | delete_pluto_event cannot delete NULL event<br>Jun 11 11:17:34.935718: | state #218 requesting N/A-pe@(nil) be deleted<br>Jun 11 11:17:34.935720: | delete_pluto_event cannot delete NULL event<br>Jun 11 11:17:34.935725: | event_schedule: new EVENT_SA_EXPIRE-pe@0x56205dcd6cc8<br>Jun 11 11:17:34.935731: | inserting event EVENT_SA_EXPIRE, timeout in 0.000 seconds for #218<br>Jun 11 11:17:34.935740: | free_event_entry: release EVENT_SA_REPLACE-pe@0x56205dcca398<br>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)<br>Jun 11 11:17:34.935748: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:34.935751: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:34.935759: | timer_event_cb: processing event@0x56205dcd6cc8<br>Jun 11 11:17:34.935762: | handling event EVENT_SA_EXPIRE for child state #218<br>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)<br>Jun 11 11:17:34.935769: | EVENT_SA_EXPIRE picked newest_ipsec_sa<br>Jun 11 11:17:34.935772: | un-established partial ISAKMP SA timeout (SA expired)<br>Jun 11 11:17:34.935775: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:34.935778: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>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)<br>Jun 11 11:17:34.935786: | serialno table: hash serialno #218 to head 0x56205ca822a0<br>Jun 11 11:17:34.935789: | serialno table: hash serialno #218 to head 0x56205ca822a0<br>Jun 11 11:17:34.935794: "vpn/1x11" #218: deleting state (STATE_V2_CREATE_I0) and NOT sending notification<br>Jun 11 11:17:34.935798: | child state #218: STATE_V2_CREATE_I0(established-authenticated-ike) => delete<br>Jun 11 11:17:34.935801: | state #218 requesting N/A-pe@(nil) be deleted<br>Jun 11 11:17:34.935804: | delete_pluto_event cannot delete NULL event <br>Jun 11 11:17:34.935807: | state #218 requesting N/A-pe@(nil) be deleted<br>Jun 11 11:17:34.935809: | delete_pluto_event cannot delete NULL event <br>Jun 11 11:17:34.935812: | state #218 requesting N/A-pe@(nil) be deleted<br>Jun 11 11:17:34.935815: | delete_pluto_event cannot delete NULL event<br>Jun 11 11:17:34.935818: | state #218 requesting N/A-pe@(nil) be deleted<br>Jun 11 11:17:34.935821: | delete_pluto_event cannot delete NULL event<br>Jun 11 11:17:34.935824: | disconnecting state #218 from md<br>Jun 11 11:17:34.935829: | child state #218: STATE_V2_CREATE_I0(established-authenticated-ike) => STATE_CHILDSA_DEL(informational)<br>Jun 11 11:17:34.935832: | ignore states: 0</font></div><div dir="ltr"><span style="color:rgb(7,55,99);font-family:verdana,sans-serif"><br></span></div></div></blockquote><span style="color:rgb(7,55,99);font-family:verdana,sans-serif"><span class="gmail_default" style="font-family:verdana,sans-serif;color:rgb(7,55,99)">Or this one:</span></span><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><div><span style="color:rgb(7,55,99);font-family:verdana,sans-serif"><span class="gmail_default" style="font-family:verdana,sans-serif;color:rgb(7,55,99)"></span></span></div><font face="monospace">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]<br>Jun 11 11:17:02.313839: | find_connection: first OK "vpn/1x12" [pri:29417482]{0x56205dc968b8} (child none)<br>Jun 11 11:17:02.313844: | find_connection: concluding with "vpn/1x12" [pri:29417482]{0x56205dc968b8} kind=CK_PERMANENT<br>Jun 11 11:17:02.313848: | assign hold, routing was prospective erouted, needs to be erouted HOLD<br>Jun 11 11:17:02.313851: | assign_holdpass() need broad(er) shunt<br>Jun 11 11:17:02.313854: | priority calculation of connection "vpn/1x12" is 0xfe3e3<br>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)<br>Jun 11 11:17:02.313863: | netlink_raw_eroute: SPI_HOLD implemented as no-op<br>Jun 11 11:17:02.313867: | raw_eroute result=success<br>Jun 11 11:17:02.313870: | assign_holdpass() eroute_connection() done<br>Jun 11 11:17:02.313873: | fiddle_bare_shunt called<br>Jun 11 11:17:02.313876: | fiddle_bare_shunt with transport_proto 1<br>Jun 11 11:17:02.313879: | removing specific host-to-host bare shunt<br>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)<br>Jun 11 11:17:02.313886: | netlink_raw_eroute: SPI_PASS<br>Jun 11 11:17:02.313895: | raw_eroute result=success<br>Jun 11 11:17:02.313899: | raw_eroute with op='delete' for transport_proto='1' kernel shunt succeeded, bare shunt lookup succeeded<br>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<br>Jun 11 11:17:02.313906: assign_holdpass() delete_bare_shunt() failed<br>Jun 11 11:17:02.313909: initiate_ondemand_body() failed to install negotiation_shunt,<br>Jun 11 11:17:02.313916: | creating state object #219 at 0x56205dcc92c8<br>Jun 11 11:17:02.313920: | parent state #219: new => STATE_UNDEFINED(ignore)<br>Jun 11 11:17:02.313923: | duplicating state object #165 "vpn/1x18" as #219 for IPSEC SA<br>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)<br>Jun 11 11:17:02.313935: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:02.313938: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:02.313942: | child state #219: STATE_UNDEFINED(ignore) => STATE_V2_CREATE_I0(established-authenticated-ike)<br>Jun 11 11:17:02.313944: | ignore states: 0<br>Jun 11 11:17:02.313947: | half-open-ike states: 0<br>Jun 11 11:17:02.313950: | open-ike states: 0<br>Jun 11 11:17:02.313953: | established-anonymous-ike states: 0<br>Jun 11 11:17:02.313956: | established-authenticated-ike states: 7<br>Jun 11 11:17:02.313959: | anonymous-ipsec states: 0<br>Jun 11 11:17:02.313962: | authenticated-ipsec states: 4<br>Jun 11 11:17:02.313964: | informational states: 0<br>Jun 11 11:17:02.313967: | unknown states: 0<br>Jun 11 11:17:02.313970: | category states: 11 count states: 11<br>Jun 11 11:17:02.313973: | inserting state object #219<br>Jun 11 11:17:02.313978: | serialno list: inserting object 0x56205dcc92c8 (state #219) entry 0x56205dcc9a70 into list 0x56205ca8d840 (older 0x56205dcdfb10 newer 0x56205dcb89f0)<br>Jun 11 11:17:02.313982: | serialno list: inserted object 0x56205dcc92c8 (state #219) entry 0x56205dcc9a70 (older 0x56205dcdfb10 newer 0x56205ca8d840)<br>Jun 11 11:17:02.313986: | serialno list: list entry 0x56205ca8d840 is HEAD (older 0x56205dcc9a70 newer 0x56205dcb89f0)<br>Jun 11 11:17:02.313990: | serialno table: inserting object 0x56205dcc92c8 (state #219) entry 0x56205dcc9a90 into list 0x56205ca822c0 (older 0x56205ca822c0 newer 0x56205ca822c0)<br>Jun 11 11:17:02.313994: | serialno table: inserted object 0x56205dcc92c8 (state #219) entry 0x56205dcc9a90 (older 0x56205ca822c0 newer 0x56205ca822c0)<br>Jun 11 11:17:02.313999: | serialno table: list entry 0x56205ca822c0 is HEAD (older 0x56205dcc9a90 newer 0x56205dcc9a90)<br>Jun 11 11:17:02.314003: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:02.314006: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:02.314015: | constructing ESP/AH proposals with default DH MODP2048 for vpn/1x12 (ESP/AH initiator emitting proposals)<br>Jun 11 11:17:02.314020: | converting proposal AES_CBC_256-HMAC_SHA2_256_128 to ikev2 ...<br>Jun 11 11:17:02.314027: | ... ikev2_proposal: 1:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_256_128;DH=MODP2048;ESN=DISABLED<br>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<br>Jun 11 11:17:02.314036: | DH ike_alg_lookup_by_id id: MODP2048=14, found MODP2048<br>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<br>Jun 11 11:17:02.314044: | state #219 requesting to delete non existing event<br>Jun 11 11:17:02.314048: | event_schedule: new EVENT_v2_INITIATE_CHILD-pe@0x56205dcd6cc8<br>Jun 11 11:17:02.314053: | inserting event EVENT_v2_INITIATE_CHILD, timeout in 0.000 seconds for #219<br>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)<br>Jun 11 11:17:02.314063: | initiate on demand using RSASIG from xxx.xxx.xxx.94 to xxx.xxx.xxx.22<br>Jun 11 11:17:02.314072: | timer_event_cb: processing event@0x56205dcd6cc8<br>Jun 11 11:17:02.314075: | handling event EVENT_v2_INITIATE_CHILD for child state #219<br>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)<br>Jun 11 11:17:02.314083: | Calling ikev2_crypto_start() from ikev2_child_outI in state STATE_V2_CREATE_I0<br>Jun 11 11:17:02.314087: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:02.314090: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:02.314095: | adding Child Initiator KE and nonce ni work-order 313 for state #219<br>Jun 11 11:17:02.314098: | state #219 requesting to delete non existing event<br>Jun 11 11:17:02.314102: | event_schedule: new EVENT_CRYPTO_TIMEOUT-pe@0x56205dcb8108<br>Jun 11 11:17:02.314106: | inserting event EVENT_CRYPTO_TIMEOUT, timeout in 60.000 seconds for #219<br>Jun 11 11:17:02.314111: | backlog: inserting object 0x56205dcc18a8 (work-order 313 state #219) entry 0x56205dcc18b0 into list 0x56205ca8e740 (older 0x56205ca8e740 newer 0x56205ca8e740)<br>Jun 11 11:17:02.314115: | backlog: inserted object 0x56205dcc18a8 (work-order 313 state #219) entry 0x56205dcc18b0 (older 0x56205ca8e740 newer 0x56205ca8e740)<br>Jun 11 11:17:02.314118: | backlog: list entry 0x56205ca8e740 is HEAD (older 0x56205dcc18b0 newer 0x56205dcc18b0)<br>Jun 11 11:17:02.314135: | crypto helper 1 resuming<br>Jun 11 11:17:02.314140: | backlog: removing object 0x56205dcc18a8 (work-order 313 state #219) entry 0x56205dcc18b0 (older 0x56205ca8e740 newer 0x56205ca8e740)<br>Jun 11 11:17:02.314143: | backlog: empty<br>Jun 11 11:17:02.314147: | crypto helper 1 starting work-order 313 for state #219<br>Jun 11 11:17:02.314151: | crypto helper 1 doing build KE and nonce; request ID 313<br>Jun 11 11:17:02.314166: | NSS: Value of Prime:<br><span class="gmail_default" style="color:rgb(7,55,99)">...<br></span>Jun 11 11:17:02.315908: | crypto helper 1 finished build KE and nonce; request ID 313 time elapsed 1758 usec<br></font></blockquote><blockquote style="margin:0 0 0 40px;border:none;padding:0px"><font face="monospace">Jun 11 11:17:02.315912: | crypto helper 1 sending results from work-order 313 for state #219 to event queue<br>Jun 11 11:17:02.315915: | scheduling now-event sending helper answer for #219<br>Jun 11 11:17:02.315921: | crypto helper 1 waiting (nothing to do)<br>Jun 11 11:17:02.315930: | free_event_entry: release EVENT_v2_INITIATE_CHILD-pe@0x56205dcd6cc8<br>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)<br>Jun 11 11:17:02.315939: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:02.315942: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:02.315952: | executing now-event sending helper answer for 219<br>Jun 11 11:17:02.315955: | serialno table: hash serialno #219 to head 0x56205ca822c0<br>Jun 11 11:17:02.315958: | serialno table: hash serialno #219 to head 0x56205ca822c0<br>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)<br>Jun 11 11:17:02.315966: | crypto helper 1 replies to request ID 313<br>Jun 11 11:17:02.315968: | calling continuation function 0x56205c79f9f0<br>Jun 11 11:17:02.315972: | ikev2_crypto_continue for #219<br>Jun 11 11:17:02.315975: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:02.315978: | serialno table: hash serialno #165 to head 0x56205ca81c00<br>Jun 11 11:17:02.315982: | wire (crypto helper) group MODP2048 and state group MODP2048 match<br>Jun 11 11:17:02.315986: | DH secret MODP2048@0x7f3d90045288: transferring ownership from helper KE to state #219<br>Jun 11 11:17:02.315990: | state #219 requesting EVENT_CRYPTO_TIMEOUT to be deleted<br>Jun 11 11:17:02.315998: | free_event_entry: release EVENT_CRYPTO_TIMEOUT-pe@0x56205dcb8108<br>Jun 11 11:17:02.316001: | event_schedule: new EVENT_SA_REPLACE-pe@0x56205dcb8108<br>Jun 11 11:17:02.316005: | inserting event EVENT_SA_REPLACE, timeout in 200.000 seconds for #219<br>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<br>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<br>Jun 11 11:17:02.316020: | suspending state #219 and saving MD<br>Jun 11 11:17:02.316023: | #219 is busy; has a suspended MD<br>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)<br>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<br>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)<br>Jun 11 11:17:02.316039: | serialno table: hash serialno #0 to head 0x56205ca80760<br>Jun 11 11:17:02.316042: | serialno table: hash serialno #0 to head 0x56205ca80760</font></blockquote><div><div class="gmail_quote"><div dir="ltr"><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">Could you please help us with some possible cause we are missing here?</div><div style="font-family:verdana,sans-serif;color:#073763">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?</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">Thanks in advance,</div><div style="font-family:verdana,sans-serif;color:#073763"><br></div><div style="font-family:verdana,sans-serif;color:#073763">Best regards!</div><div><br></div>-- <br><div dir="ltr" data-smartmail="gmail_signature"><div dir="ltr"><div><div dir="ltr"><div>
<div><div>
<div><div>
<div><div>
<div><br>
<img alt="Logo Especialidad" src="https://webs.paradigmadigital.com/pd-signature/img/Sistemaschico.png" width="60">
<p><strong><span style="margin-top:10px;font-size:17px;color:black">Miguel Ponce Antolín</span><span style="color:rgb(255,69,67);font-size:16px">.</span></strong><br>
<span style="font-size:11px;color:black">Sistemas</span>
<span style="font-size:11px;color:black"> · +34 670 360 655</span><br>
<img style="margin-top:10px;margin-bottom:10px" alt="Linea" src="https://webs.paradigmadigital.com/pd-signature/img/linea.png"><br>
<img alt="Logo Paradigma" src="https://webs.paradigmadigital.com/pd-signature/img/logo.png" width="14">
<span style="color:rgb(24,31,44);font-size:11px">·</span>
<a style="color:rgb(24,31,44);text-decoration:none" href="https://www.paradigmadigital.com/" target="_blank"><font size="1">paradig.ma</font></a>
<span style="color:rgb(24,31,44);font-size:11px">·</span>
<a style="color:rgb(24,31,44);text-decoration:none" href="https://www.paradigmadigital.com/contacto" target="_blank"><font size="1">contáctanos</font></a>
<span style="color:rgb(24,31,44);font-size:11px">·</span>
<a href="https://twitter.com/paradigmate" target="_blank"><img style="margin-top:2px" alt="Twitter" src="https://webs.paradigmadigital.com/pd-signature/img/twitter.png" width="13"></a>
<a href="https://www.youtube.com/user/ParadigmaTe?feature=watch" target="_blank"><img style="margin-top:2px" alt="Youtube" src="https://webs.paradigmadigital.com/pd-signature/img/youtube.png" width="13"></a>
<a href="https://www.linkedin.com/company/paradigma-digital/" target="_blank"><img style="margin-top:2px" alt="Linkedin" src="https://webs.paradigmadigital.com/pd-signature/img/linkedin.png" width="13"></a>
<a href="https://www.instagram.com/paradigma_digital/?hl=es" target="_blank"><img style="margin-top:2px" alt="Instagram" src="https://webs.paradigmadigital.com/pd-signature/img/instagram.png" width="13"></a>
</p>
</div>
</div></div>
</div></div>
</div></div>
</div></div></div></div></div></div>
</div><div><br></div><div dir="ltr" data-smartmail="gmail_signature"><div dir="ltr"><div><div dir="ltr"><div><div><div><div><div><div><div><div>
</div>
</div></div>
</div></div>
</div></div>
</div></div></div></div></div></div></div>