[Swan] One more hi-rekey cycling issue

Tue Nov 6 21:58:59 UTC 2018

Previously, we mentioned this issue:
https://lists.libreswan.org/pipermail/swan/2018/002759.html which
more-or-less appears to be working as designed, although I have not seen
the specific pattern since our 3.25 upgrade.

However, we have a new infinitely loop that appears to occur completely on
our side, with no delete payload/re-initiate prompted by the other side.

We started with a connection that looked like this:
000 #439457: "essentia342/2x3":500 STATE_QUICK_I1 (sent QI1, expecting
QR1); EVENT_v1_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle;
import:admin initiate
000 #439452: "essentia342/2x4":500 STATE_QUICK_I1 (sent QI1, expecting
QR1); EVENT_v1_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle;
import:admin initiate
000 #439459: "essentia342/2x5":500 STATE_QUICK_I1 (sent QI1, expecting
QR1); EVENT_v1_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle;
import:admin initiate
000 #439463: "essentia342/2x6":500 STATE_QUICK_I1 (sent QI1, expecting
QR1); EVENT_v1_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle;
import:admin initiate
000 #439455: "essentia342/2x7":500 STATE_QUICK_I1 (sent QI1, expecting
QR1); EVENT_v1_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle;
import:admin initiate
000 #336954: "essentia342/2x8":500 STATE_MAIN_I4 (ISAKMP SA established);
EVENT_SA_REPLACE in 51115s; newest ISAKMP; lastdpd=34438s(seq in:18617
out:18616); idle; import:admin initiate
000 #439406: "essentia342/2x8":500 STATE_QUICK_I1 (sent QI1, expecting
QR1); EVENT_v1_RETRANSMIT in 30s; lastdpd=-1s(seq in:0 out:0); idle;
import:admin initiate
000 #439464: "essentia342/2x8":500 STATE_QUICK_I1 (sent QI1, expecting
QR1); EVENT_v1_RETRANSMIT in 6s; lastdpd=-1s(seq in:0 out:0); idle;
import:admin initiate

We did a delete -- which deleted the duplicate 2x8 SAs:
root at ip-172-20-109-76(vpn):/etc/ipsec.d# ipsec auto --delete essentia342
002 "essentia342/1x1": deleting non-instance connection
002 "essentia342/1x1" #439986: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x2": deleting non-instance connection
002 "essentia342/1x2" #439988: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x3": deleting non-instance connection
002 "essentia342/1x3" #439996: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x4": deleting non-instance connection
002 "essentia342/1x4" #439990: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x5": deleting non-instance connection
002 "essentia342/1x5" #439984: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x6": deleting non-instance connection
002 "essentia342/1x6" #439995: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x7": deleting non-instance connection
002 "essentia342/1x7" #439982: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x8": deleting non-instance connection
002 "essentia342/1x8" #439983: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x1": deleting non-instance connection
002 "essentia342/2x1" #439992: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x2": deleting non-instance connection
002 "essentia342/2x2" #439999: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x3": deleting non-instance connection
002 "essentia342/2x3" #439994: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x4": deleting non-instance connection
002 "essentia342/2x4" #439987: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x5": deleting non-instance connection
002 "essentia342/2x5" #439998: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x6": deleting non-instance connection
002 "essentia342/2x6" #439989: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x7": deleting non-instance connection
002 "essentia342/2x7" #439991: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x8": deleting non-instance connection
002 "essentia342/2x8" #439997: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x8" #439941: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x8" #336954: deleting state (STATE_MAIN_I4) and sending
notification

And then an add + up.  Then we see this:

000 initiating all conns with alias='essentia342'
002 "essentia342/2x8" #440083: initiating Main Mode
104 "essentia342/2x8" #440083: STATE_MAIN_I1: initiate
106 "essentia342/2x8" #440083: STATE_MAIN_I2: sent MI2, expecting MR2
003 "essentia342/2x8" #440083: ignoring unknown Vendor ID payload
[407f3135484ae73200fd5aea12860ac1]
108 "essentia342/2x8" #440083: STATE_MAIN_I3: sent MI3, expecting MR3
002 "essentia342/2x8" #440083: Peer ID is ID_IPV4_ADDR: '208.72.50.5'
004 "essentia342/2x8" #440083: STATE_MAIN_I4: ISAKMP SA established
{auth=PRESHARED_KEY cipher=aes_256 integ=sha group=MODP1024}
002 "essentia342/1x1" #440084: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:1e1513ae proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/1x2" #440085: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:818e30fd proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/1x3" #440086: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:7300d1e7 proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/1x4" #440087: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:0b634865 proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/1x5" #440088: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:37009e4d proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/1x6" #440089: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:aadcfe62 proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/1x7" #440090: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:e0a5804b proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/1x8" #440091: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:49516e46 proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x1" #440092: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:3e212fef proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x2" #440093: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:c4f7723a proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x3" #440094: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:42a2235c proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x4" #440095: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:4ccedfc0 proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x5" #440096: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:9991df3c proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x6" #440097: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:f0d98ebf proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x7" #440098: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:ac901015 proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
002 "essentia342/2x8" #440099: initiating Quick Mode
PSK+ENCRYPT+TUNNEL+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
{using isakmp#440083 msgid:2f8933e7 proposal=AES_CBC_256-HMAC_SHA1_96
pfsgroup=no-pfs}
117 "essentia342/1x1" #440084: STATE_QUICK_I1: initiate
117 "essentia342/1x2" #440085: STATE_QUICK_I1: initiate
117 "essentia342/1x3" #440086: STATE_QUICK_I1: initiate
117 "essentia342/1x4" #440087: STATE_QUICK_I1: initiate
117 "essentia342/1x5" #440088: STATE_QUICK_I1: initiate
117 "essentia342/1x6" #440089: STATE_QUICK_I1: initiate
117 "essentia342/2x5" #440096: STATE_QUICK_I1: initiate
117 "essentia342/2x6" #440097: STATE_QUICK_I1: initiate
117 "essentia342/2x7" #440098: STATE_QUICK_I1: initiate
117 "essentia342/1x7" #440090: STATE_QUICK_I1: initiate
117 "essentia342/2x1" #440092: STATE_QUICK_I1: initiate
117 "essentia342/2x3" #440094: STATE_QUICK_I1: initiate
117 "essentia342/2x4" #440095: STATE_QUICK_I1: initiate
117 "essentia342/2x2" #440093: STATE_QUICK_I1: initiate
117 "essentia342/1x8" #440091: STATE_QUICK_I1: initiate
117 "essentia342/2x8" #440099: STATE_QUICK_I1: initiate
002 "essentia342/2x8" #440100: initiating Main Mode
104 "essentia342/2x8" #440100: STATE_MAIN_I1: initiate
002 "essentia342/2x8" #440099: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x1" #440084: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x7" #440098: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x6" #440097: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x2" #440085: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x1" #440092: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x8" #440091: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x7" #440090: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x6" #440089: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x3" #440086: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x4" #440087: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x5" #440096: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x4" #440095: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x3" #440094: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/2x2" #440093: deleting state (STATE_QUICK_I1) and NOT
sending notification
002 "essentia342/1x5" #440088: deleting state (STATE_QUICK_I1) and NOT
sending notification
106 "essentia342/2x8" #440100: STATE_MAIN_I2: sent MI2, expecting MR2
003 "essentia342/2x8" #440100: ignoring unknown Vendor ID payload
[429e086feff7624108a08c8b1dcf4e8a]
108 "essentia342/2x8" #440100: STATE_MAIN_I3: sent MI3, expecting MR3
002 "essentia342/2x8" #440100: Peer ID is ID_IPV4_ADDR: '208.72.50.5'

This cycles indefinitely.  I don't see anything that explains why we are
re-keying.  We deleted the connection manually, and we re-added it later in
the afternoon.  Then it connected without a problem.  No changes had been
made on either side.

It appears to be working now, so there's not a lot of urgency, but we're
concerned about it happening again and causing high load.  Any thoughts
would be appreciated.

-Dharma
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20181106/fbc0cf77/attachment-0001.html>