[Swan] mis-matched phase 2 settings cause infinite rekeys, high load, and broad failure across unrelated tunnels
Dharma Indurthy
dharma at redoxengine.com
Fri Oct 19 21:04:35 UTC 2018
Hey, folks.
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.
ipsec verify:
Verifying installed system and configuration files
Version check and ipsec on-path [OK]
Libreswan 3.25 (netkey) on 4.15.0-1020-aws
Checking for IPsec support in kernel [OK]
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.
We added this config:
conn baycare4059
type=tunnel
authby=secret
left=<our gateway internal ip>
leftid=<out gateway public ip>
leftsourceip=<our gateway internal ip>
leftsubnets=" <ls1> <ls2> "
right=<customer peer ip>
rightsubnets=" <rs1> <rs2> "
rightsourceip=<customer peer ip>
auto=start
ike=aes256-sha1;modp1536
phase2alg=aes256-sha1;modp1536
ikelifetime=86400
salifetime=3600
dpdaction=restart
dpddelay=30
dpdtimeout=120
pfs=yes
*Here's the beginning of the logs. We haven't reread secrets, so we can't
connect:*
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
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
Oct 18 14:50:37 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360027:
no acceptable Oakley Transform
Oct 18 14:50:37 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360027:
sending notification NO_PROPOSAL_CHOSEN to 204.76.135.13:500
*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:*
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'
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}
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}
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}
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}
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}
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 00 3c 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "southdenvergastro3801/2x3"
#4307776: received and ignored informational message
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091:
received and ignored informational message
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091:
received Delete SA payload: self-deleting ISAKMP State #4360091
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360091:
deleting state (STATE_MAIN_I4) and sending notification
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
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
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
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: packet from
204.76.135.13:4500: received and ignored empty informational notification
payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
initiating Main Mode
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360116:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360115:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360114:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360113:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
STATE_MAIN_I2: sent MI2, expecting MR2
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
ignoring unknown Vendor ID payload [cd8b8b43760156a39c663cf73b09aa7b]
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
STATE_MAIN_I3: sent MI3, expecting MR3
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
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'
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}
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}
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}
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}
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}
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
received and ignored informational message
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
received and ignored informational message
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
received and ignored informational message
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
received and ignored informational message
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
received Delete SA payload: self-deleting ISAKMP State #4360117
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360117:
deleting state (STATE_MAIN_I4) and sending notification
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
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
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
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: packet from
204.76.135.13:4500: received and ignored empty informational notification
payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
initiating Main Mode
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360121:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360120:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360119:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360118:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
STATE_MAIN_I2: sent MI2, expecting MR2
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
ignoring unknown Vendor ID payload [f4968e3e3efe77f10488a89c530178cd]
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
STATE_MAIN_I3: sent MI3, expecting MR3
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
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 00 40 00 00 00
00 01 10 00 0e
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "shoreortho3301/2x1"
#4360097: received and ignored informational message
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
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'
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}
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}
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}
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}
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}
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
received and ignored informational message
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
received and ignored informational message
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
received and ignored informational message
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
received and ignored informational message
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
received Delete SA payload: self-deleting ISAKMP State #4360122
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360122:
deleting state (STATE_MAIN_I4) and sending notification
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
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
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
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
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: packet from
204.76.135.13:4500: received and ignored empty informational notification
payload
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127:
initiating Main Mode
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360126:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4360125:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4360124:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4360123:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127:
STATE_MAIN_I2: sent MI2, expecting MR2
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127:
ignoring unknown Vendor ID payload [f10c2a922228ff7832639e9b9d9b9039]
Oct 18 14:51:25 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4360127:
STATE_MAIN_I3: sent MI3, expecting MR3
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
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'
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}
*We have no limit on keying retries, so this continues for a few minutes.
We delete the connection, and things settle down:*
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2": deleting
non-instance connection
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363028:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363024:
deleting state (STATE_MAIN_I4) and sending notification
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
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
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
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1": deleting
non-instance connection
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4363027:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2": deleting
non-instance connection
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4363026:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1": deleting
non-instance connection
Oct 18 14:52:45 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4363025:
deleting state (STATE_QUICK_I1) and NOT sending notification
*But then we try initiating again, and the loop predictably resumes:*
Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: initiating all conns with
alias='baycare4059'
Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088:
initiating Main Mode
Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088:
STATE_MAIN_I2: sent MI2, expecting MR2
Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088:
ignoring unknown Vendor ID payload [df928b0e789937edb548a96539525a0e]
Oct 18 14:53:39 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363088:
STATE_MAIN_I3: sent MI3, expecting MR3
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
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'
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}
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}
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}
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}
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}
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
*This goes on for a ~5 seconds, and then pluto stops logging anything:*
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'
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}
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}
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}
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}
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}
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
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294:
received and ignored informational message
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
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294:
received and ignored informational message
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
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294:
received and ignored informational message
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
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | ISAKMP Notification Payload
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: | 00 00 01 60 00 00 00
01 03 04 00 12
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294:
received and ignored informational message
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294:
received Delete SA payload: self-deleting ISAKMP State #4363294
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363294:
deleting state (STATE_MAIN_I4) and sending notification
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
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
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
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
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: packet from
204.76.135.13:4500: received and ignored empty informational notification
payload
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363299:
initiating Main Mode
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x2" #4363298:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/2x1" #4363297:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/1x2" #4363296:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:53:44 ip-172-20-109-76 pluto[23193]: "baycare4059/1x1" #4363295:
deleting state (STATE_QUICK_I1) and NOT sending notification
Oct 18 14:54:01 ip-172-20-109-76 CRON[24597]: pam_unix(cron:session):
session opened for user root by (uid=0)
*We hit the watchdog limit, and systemd kills pluto and restarts:*
Oct 18 14:56:18 ip-172-20-109-76 systemd[1]: ipsec.service: Watchdog
timeout (limit 3min 20s)!
Oct 18 14:56:18 ip-172-20-109-76 systemd[1]: ipsec.service: Killing
process 23193 (pluto) with signal SIGABRT.
*Here's some output from the core dump:*
ProblemType: Crash
Architecture: amd64
Date: Thu Oct 18 14:56:18 2018
DistroRelease: Ubuntu 18.04
ExecutablePath: /usr/lib/ipsec/pluto
ExecutableTimestamp: 1530118004
ProcCmdline: /usr/lib/ipsec/pluto --leak-detective --config /etc/ipsec.conf
--nofork
ProcCwd: /run/pluto
ProcEnviron:
LANG=C.UTF-8
PATH=(custom, no user)
ProcStatus:
Name: pluto
Umask: 0022
State: S (sleeping)
Tgid: 23193
Ngid: 0
Pid: 23193
PPid: 1
TracerPid: 0
Uid: 0 0 0 0
Gid: 0 0 0 0
FDSize: 64
Groups:
NStgid: 23193
NSpid: 23193
NSpgid: 23193
NSsid: 23193
VmPeak: 1109020 kB
VmSize: 1049672 kB
VmLck: 0 kB
VmPin: 0 kB
VmHWM: 792004 kB
VmRSS: 792004 kB
RssAnon: 779176 kB
RssFile: 12828 kB
RssShmem: 0 kB
VmData: 803300 kB
VmStk: 132 kB
VmExe: 1344 kB
VmLib: 24864 kB
VmPTE: 1872 kB
VmSwap: 0 kB
HugetlbPages: 0 kB
CoreDumping: 1
Threads: 4
SigQ: 0/62213
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000001000
SigCgt: 0000000180014001
CapInh: 0000000000000000
CapPrm: 00000000200074c4
CapEff: 00000000200074c4
CapBnd: 0000000000003004
CapAmb: 0000000000000000
NoNewPrivs: 0
Seccomp: 0
Speculation_Store_Bypass: vulnerable
Cpus_allowed: f
Cpus_allowed_list: 0-3
Mems_allowed:
00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,000
00000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,0000
0000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list: 0
voluntary_ctxt_switches: 19190080
nonvoluntary_ctxt_switches: 3124929
Signal: 6
Uname: Linux 4.15.0-1020-aws x86_64
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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20181019/1409798c/attachment-0001.html>
More information about the Swan
mailing list