<div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr">Hey, folks.<div><br></div><div>My colleague Terell described this issue about a month ago.  For background, we have libreswan server running that supports ~150 connections.  We proceeded with a libreswan upgrade to 3.25.<br><br>ipsec verify:<br><div>Verifying installed system and configuration files</div><div><br></div><div>Version check and ipsec on-path                   <span style="white-space:pre">    </span>[OK]</div><div>Libreswan 3.25 (netkey) on 4.15.0-1020-aws</div><div>Checking for IPsec support in kernel              <span style="white-space:pre">        </span>[OK]</div><div><br></div></div><div>The upgrade seemed to be successful.  However, we just encountered the infinite look rekey problem.  What appeared to happen is that the re-keys looped like crazy and persisted until pluto became unresponsive, and systemd then killed the process.  Here's the gist.</div><div><br></div><div>We added this config:</div><div><div>conn baycare4059</div><div>    type=tunnel</div><div>    authby=secret</div><div>    left=<our gateway internal ip></div><div>    leftid=<out gateway public ip></div><div>    leftsourceip=<our gateway internal ip></div><div>    leftsubnets=" <ls1> <ls2> "</div><div>    right=<customer peer ip></div><div>    rightsubnets=" <rs1> <rs2> "</div><div>    rightsourceip=<customer peer ip></div><div>    auto=start</div><div>    ike=aes256-sha1;modp1536</div><div>    phase2alg=aes256-sha1;modp1536</div><div>    ikelifetime=86400</div><div>    salifetime=3600</div><div>    dpdaction=restart</div><div>    dpddelay=30</div><div>    dpdtimeout=120</div><div>    pfs=yes</div></div><div><br></div><div><b>Here's the beginning of the logs.  We haven't reread secrets, so we can't connect:</b></div><div><div>Oct 18 14:50:37 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360027: STATE_MAIN_I1: retransmission; will wait 16 seconds for response</div><div>Oct 18 14:50:37 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360027: Can't authenticate: no preshared key found for `52.205.166.91' and `204.76.135.13'.  Attribute OAKLEY_AUTHENTICATION_METHOD<br></div><div>Oct 18 14:50:37 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360027: no acceptable Oakley Transform</div><div>Oct 18 14:50:37 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360027: sending notification NO_PROPOSAL_CHOSEN to <a href="http://204.76.135.13:500">204.76.135.13:500</a></div></div><div><br></div><div><b>So then we fix the secret, reread, and encounter an infinite loop.  We still don't know what if any configuration mismatch there is.  The connection logs like crazy.  The logs below represent a fraction of a second:</b><br><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: Peer ID is ID_IPV4_ADDR: '204.76.135.13'</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_256 integ=sha group=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360113: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4360091 msgid:62ca303f proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360114: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4360091 msgid:ceca2e6d proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360115: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4360091 msgid:cbbfdcb9 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360116: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4360091 msgid:d616b6b4 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "southdenvergastro3801/2x3" #4307776: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=60</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 00 3c  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "southdenvergastro3801/2x3" #4307776: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: received Delete SA payload: self-deleting ISAKMP State #4360091</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: deleting state (STATE_MAIN_I4) and sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: reschedule pending child #4360116 STATE_QUICK_I1 of connection "baycare4059/2x2" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: reschedule pending child #4360115 STATE_QUICK_I1 of connection "baycare4059/2x1" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: reschedule pending child #4360114 STATE_QUICK_I1 of connection "baycare4059/1x2" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091: reschedule pending child #4360113 STATE_QUICK_I1 of connection "baycare4059/1x1" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: packet from <a href="http://204.76.135.13:4500">204.76.135.13:4500</a>: received and ignored empty informational notification payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: initiating Main Mode</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360116: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360115: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360114: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360113: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: STATE_MAIN_I2: sent MI2, expecting MR2</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "radboud1053/2x2" #4360098: STATE_MAIN_I3: retransmission; will wait 8 seconds for response</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: ignoring unknown Vendor ID payload [cd8b8b43760156a39c663cf73b09aa7b]</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: STATE_MAIN_I3: sent MI3, expecting MR3</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | protocol/port in Phase 1 ID Payload is 17/0. accepted with port_floating NAT-T</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: Peer ID is ID_IPV4_ADDR: '204.76.135.13'</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_256 integ=sha group=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360118: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4360113 {using isakmp#4360117 msgid:3a969c75 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360119: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4360114 {using isakmp#4360117 msgid:d9b3fc86 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360120: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4360115 {using isakmp#4360117 msgid:390538f0 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360121: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4360117 msgid:7c820da7 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: received Delete SA payload: self-deleting ISAKMP State #4360117</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: deleting state (STATE_MAIN_I4) and sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: reschedule pending child #4360121 STATE_QUICK_I1 of connection "baycare4059/2x2" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: reschedule pending child #4360120 STATE_QUICK_I1 of connection "baycare4059/2x1" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: reschedule pending child #4360119 STATE_QUICK_I1 of connection "baycare4059/1x2" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117: reschedule pending child #4360118 STATE_QUICK_I1 of connection "baycare4059/1x1" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: packet from <a href="http://204.76.135.13:4500">204.76.135.13:4500</a>: received and ignored empty informational notification payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: initiating Main Mode</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360121: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360120: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360119: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360118: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: STATE_MAIN_I2: sent MI2, expecting MR2</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: ignoring unknown Vendor ID payload [f4968e3e3efe77f10488a89c530178cd]</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: STATE_MAIN_I3: sent MI3, expecting MR3</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "drarashdini3936/2x2" #4360090: STATE_MAIN_I3: retransmission; will wait 8 seconds for response</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "shoreortho3301/2x1" #4360097: ignoring informational payload NO_PROPOSAL_CHOSEN, msgid=00000000, length=64</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 00 40  00 00 00 00  01 10 00 0e</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "shoreortho3301/2x1" #4360097: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | protocol/port in Phase 1 ID Payload is 17/0. accepted with port_floating NAT-T</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: Peer ID is ID_IPV4_ADDR: '204.76.135.13'</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_256 integ=sha group=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360123: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4360118 {using isakmp#4360122 msgid:4f68c383 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360124: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4360119 {using isakmp#4360122 msgid:2d599027 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360125: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4360120 {using isakmp#4360122 msgid:0fb41132 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360126: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4360122 msgid:e3249b57 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: received and ignored informational message</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: received Delete SA payload: self-deleting ISAKMP State #4360122</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: deleting state (STATE_MAIN_I4) and sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: reschedule pending child #4360126 STATE_QUICK_I1 of connection "baycare4059/2x2" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: reschedule pending child #4360125 STATE_QUICK_I1 of connection "baycare4059/2x1" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: reschedule pending child #4360124 STATE_QUICK_I1 of connection "baycare4059/1x2" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122: reschedule pending child #4360123 STATE_QUICK_I1 of connection "baycare4059/1x1" - the parent is going away</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: packet from <a href="http://204.76.135.13:4500">204.76.135.13:4500</a>: received and ignored empty informational notification payload</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127: initiating Main Mode</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360126: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360125: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360124: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360123: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127: STATE_MAIN_I2: sent MI2, expecting MR2</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127: ignoring unknown Vendor ID payload [f10c2a922228ff7832639e9b9d9b9039]</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127: STATE_MAIN_I3: sent MI3, expecting MR3</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | protocol/port in Phase 1 ID Payload is 17/0. accepted with port_floating NAT-T</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127: Peer ID is ID_IPV4_ADDR: '204.76.135.13'</div><div>Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_256 integ=sha group=MODP1536}</div></div><div><br></div><div><b>We have no limit on keying retries, so this continues for a few minutes.  We delete the connection, and things settle down:</b><br><br><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2": deleting non-instance connection</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363028: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363024: deleting state (STATE_MAIN_I4) and sending notification</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363024: reschedule pending child #4363027 STATE_QUICK_I1 of connection "baycare4059/2x1" - the parent is going away</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363024: reschedule pending child #4363026 STATE_QUICK_I1 of connection "baycare4059/1x2" - the parent is going away</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363024: reschedule pending child #4363025 STATE_QUICK_I1 of connection "baycare4059/1x1" - the parent is going away</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1": deleting non-instance connection</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4363027: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2": deleting non-instance connection</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4363026: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1": deleting non-instance connection</div><div>Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4363025: deleting state (STATE_QUICK_I1) and NOT sending notification</div></div><div><br></div><div><b>But then we try initiating again, and the loop predictably resumes:</b><br><br><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: initiating all conns with alias='baycare4059'</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088: initiating Main Mode</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088: STATE_MAIN_I2: sent MI2, expecting MR2</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088: ignoring unknown Vendor ID payload [df928b0e789937edb548a96539525a0e]</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088: STATE_MAIN_I3: sent MI3, expecting MR3</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: | protocol/port in Phase 1 ID Payload is 17/0. accepted with port_floating NAT-T</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088: Peer ID is ID_IPV4_ADDR: '204.76.135.13'</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_256 integ=sha group=MODP1536}</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4363089: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4363088 msgid:a635fb9d proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4363090: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4363088 msgid:d982d0c1 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4363091: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4363088 msgid:b74ea225 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363092: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4363088 msgid:1eddf9a7 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div></div><div><b><br></b></div><div><b>This goes on for a ~5 seconds, and then pluto stops logging anything:</b><br><br></div><div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: Peer ID is ID_IPV4_ADDR: '204.76.135.13'</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: STATE_MAIN_I4: ISAKMP SA established {auth=PRESHARED_KEY cipher=aes_256 integ=sha group=MODP1536}</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4363295: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4363290 {using isakmp#4363294 msgid:eb699266 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4363296: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4363291 {using isakmp#4363294 msgid:830bc7e8 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4363297: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #4363292 {using isakmp#4363294 msgid:f6297849 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363298: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#4363294 msgid:f8726563 proposal=AES_CBC_256-HMAC_SHA1_96-MODP1536 pfsgroup=MODP1536}</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: received and ignored informational message</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: received and ignored informational message</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: received and ignored informational message</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: ignoring informational payload INVALID_ID_INFORMATION, msgid=00000000, length=352</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: |   00 00 01 60  00 00 00 01  03 04 00 12</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: received and ignored informational message</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: received Delete SA payload: self-deleting ISAKMP State #4363294</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: deleting state (STATE_MAIN_I4) and sending notification</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: reschedule pending child #4363298 STATE_QUICK_I1 of connection "baycare4059/2x2" - the parent is going away</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: reschedule pending child #4363297 STATE_QUICK_I1 of connection "baycare4059/2x1" - the parent is going away</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: reschedule pending child #4363296 STATE_QUICK_I1 of connection "baycare4059/1x2" - the parent is going away</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294: reschedule pending child #4363295 STATE_QUICK_I1 of connection "baycare4059/1x1" - the parent is going away</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: packet from <a href="http://204.76.135.13:4500">204.76.135.13:4500</a>: received and ignored empty informational notification payload</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363299: initiating Main Mode</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363298: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4363297: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div>Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4363296: deleting state (STATE_QUICK_I1) and NOT sending notification</div><div><span style="background-color:rgb(255,255,0)">Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4363295: deleting state (STATE_QUICK_I1) and NOT sending notification</span></div><div><span style="background-color:rgb(255,255,0)">Oct 18 14:54:01 ip-172-20-109-76 CRON[24597]: pam_unix(cron:session): session opened for user root by (uid=0)</span></div><div><br></div></div><div><b>We hit the watchdog limit, and systemd kills pluto and restarts:</b></div><div><br></div><div><pre class="gmail-m gmail-m-p gmail-wr" id="gmail-" style="color:rgb(51,51,51);margin-top:0px;margin-bottom:0px;padding:0px;border:0px;outline:none;font-family:"Roboto Mono","Courier New",monospace;font-size:11px;line-height:15px;white-space:pre-wrap;overflow-y:hidden;max-height:165px">Oct 18 14:56:18 ip-172-20-109-76 systemd[1]: ipsec.service: Watchdog timeout (limit 3min 20s)!</pre><pre class="gmail-m gmail-m-p gmail-wr" id="gmail-" style="color:rgb(51,51,51);margin-top:0px;margin-bottom:0px;padding:0px;border:0px;outline:none;font-family:"Roboto Mono","Courier New",monospace;font-size:11px;line-height:15px;white-space:pre-wrap;overflow-y:hidden;max-height:165px"><pre class="gmail-m gmail-m-p gmail-wr" id="gmail-" style="background-color:rgba(225,240,250,0.6);margin-top:0px;margin-bottom:0px;padding:0px;border:0px;outline:none;font-family:"Roboto Mono","Courier New",monospace;line-height:15px;white-space:pre-wrap;overflow-y:hidden;max-height:165px">Oct 18 14:56:18 ip-172-20-109-76 systemd[1]: ipsec.service: Killing process 23193 (pluto) with signal SIGABRT.</pre></pre><pre class="gmail-m gmail-m-p gmail-wr" id="gmail-" style="color:rgb(51,51,51);margin-top:0px;margin-bottom:0px;padding:0px;border:0px;outline:none;font-family:"Roboto Mono","Courier New",monospace;font-size:11px;line-height:15px;white-space:pre-wrap;overflow-y:hidden;max-height:165px"><br></pre></div><div><b>Here's some output from the core dump:</b></div><div><br></div><div><div>ProblemType: Crash</div><div>Architecture: amd64</div><div>Date: Thu Oct 18 14:56:18 2018</div><div>DistroRelease: Ubuntu 18.04</div><div>ExecutablePath: /usr/lib/ipsec/pluto</div><div>ExecutableTimestamp: 1530118004</div><div>ProcCmdline: /usr/lib/ipsec/pluto --leak-detective --config /etc/ipsec.conf --nofork</div><div>ProcCwd: /run/pluto</div><div>ProcEnviron:</div><div> LANG=C.UTF-8</div><div> PATH=(custom, no user)</div><div><div>ProcStatus:</div><div> Name:<span style="white-space:pre">       </span>pluto</div><div> Umask:<span style="white-space:pre"> </span>0022</div><div> State:<span style="white-space:pre">  </span>S (sleeping)</div><div> Tgid:<span style="white-space:pre">   </span>23193</div><div> Ngid:<span style="white-space:pre">  </span>0</div><div> Pid:<span style="white-space:pre">       </span>23193</div><div> PPid:<span style="white-space:pre">  </span>1</div><div> TracerPid:<span style="white-space:pre"> </span>0</div><div> Uid:<span style="white-space:pre">       </span>0<span style="white-space:pre">    </span>0<span style="white-space:pre">    </span>0<span style="white-space:pre">    </span>0</div><div> Gid:<span style="white-space:pre">       </span>0<span style="white-space:pre">    </span>0<span style="white-space:pre">    </span>0<span style="white-space:pre">    </span>0</div><div> FDSize:<span style="white-space:pre">    </span>64</div><div> Groups:</div><div> NStgid:<span style="white-space:pre">   </span>23193</div><div> NSpid:<span style="white-space:pre"> </span>23193</div><div> NSpgid:<span style="white-space:pre">        </span>23193</div><div> NSsid:<span style="white-space:pre"> </span>23193</div><div> VmPeak:<span style="white-space:pre">        </span> 1109020 kB</div><div> VmSize:<span style="white-space:pre">  </span> 1049672 kB</div><div> VmLck:<span style="white-space:pre">   </span>       0 kB</div><div> VmPin:<span style="white-space:pre">       </span>       0 kB</div><div> VmHWM:<span style="white-space:pre">       </span>  792004 kB</div></div></div><div><div> VmRSS:<span style="white-space:pre">       </span>  792004 kB</div><div> RssAnon:<span style="white-space:pre">        </span>  779176 kB</div><div> RssFile:<span style="white-space:pre">        </span>   12828 kB</div><div> RssShmem:<span style="white-space:pre">      </span>       0 kB</div><div> VmData:<span style="white-space:pre">      </span>  803300 kB</div><div> VmStk:<span style="white-space:pre">  </span>     132 kB</div><div> VmExe:<span style="white-space:pre">        </span>    1344 kB</div><div> VmLib:<span style="white-space:pre"> </span>   24864 kB</div><div> VmPTE:<span style="white-space:pre"> </span>    1872 kB</div><div> VmSwap:<span style="white-space:pre">        </span>       0 kB</div><div> HugetlbPages:<span style="white-space:pre">        </span>       0 kB</div><div> CoreDumping:<span style="white-space:pre"> </span>1</div><div> Threads:<span style="white-space:pre">   </span>4</div><div> SigQ:<span style="white-space:pre">      </span>0/62213</div><div> SigPnd:<span style="white-space:pre">      </span>0000000000000000</div><div> ShdPnd:<span style="white-space:pre">     </span>0000000000000000</div><div> SigBlk:<span style="white-space:pre">     </span>0000000000000000</div><div> SigIgn:<span style="white-space:pre">     </span>0000000000001000</div><div> SigCgt:<span style="white-space:pre">     </span>0000000180014001</div></div><div><div> CapInh:<span style="white-space:pre">      </span>0000000000000000</div><div> CapPrm:<span style="white-space:pre">     </span>00000000200074c4</div><div> CapEff:<span style="white-space:pre">     </span>00000000200074c4</div><div> CapBnd:<span style="white-space:pre">     </span>0000000000003004</div><div> CapAmb:<span style="white-space:pre">     </span>0000000000000000</div><div> NoNewPrivs:<span style="white-space:pre"> </span>0</div><div> Seccomp:<span style="white-space:pre">   </span>0</div><div> Speculation_Store_Bypass:<span style="white-space:pre">  </span>vulnerable</div><div> Cpus_allowed:<span style="white-space:pre">     </span>f</div><div> Cpus_allowed_list:<span style="white-space:pre"> </span>0-3</div><div> Mems_allowed:<span style="white-space:pre">    </span>00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,000</div><div>00000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,0000</div><div>0000,00000000,00000000,00000000,00000000,00000001</div><div> Mems_allowed_list:<span style="white-space:pre">     </span>0</div><div> voluntary_ctxt_switches:<span style="white-space:pre">   </span>19190080</div><div> nonvoluntary_ctxt_switches:<span style="white-space:pre"> </span>3124929</div><div>Signal: 6</div><div>Uname: Linux 4.15.0-1020-aws x86_64</div></div><div><br></div><div>At this point, we're planning on adding a keyingretries limit to all connections and alerting on failures, but I expect it's gonna be noisy and require intervention.  If there's no way to throttle the rekey's, then not sure what else we can do.  If there are any other options, we'd love to hear it.</div></div></div></div></div></div></div></div></div></div></div></div></div>