[Swan] Tunnel drops intermittently during phase 2 rekeying

Fri Dec 14 01:56:30 UTC 2018

Hi,

I am running libreswan 3.27 and setting up IPSec tunnels between many hosts
using config like:

config setup
    protostack=netkey
    logfile=/var/log/pluto.log

conn tunnel-1
    left=123.123.123.123
    right=345.345.345.345
    authby=secret
    ikev2=insist
    ike=aes_gcm256-sha2
    phase2alg=aes_gcm256-null
    negotiationshunt=hold
    failureshunt=drop
    ikelifetime=8h
    salifetime=1h
    auto=start

Initially, all connections come up and traffics go through with no problem.
But when phase 2 rekey occurs, I see some tunnels dropping with errors. In
pluto logs, I am seeing CHILD_SA_NOT_FOUND and INVALID_IKE_SPI and it
eventually stops attempting the rekey. During next SA lifetime expiry, it
sometimes brings up the connection again successfully, but nothing occurs
again before then. To me, it looks like the issue is related to the
exchange collision described in https://wiki.strongswan.org/issues/1293,
but I am not 100% sure.

Any idea what's going on and how to resolve the issue?

Here is the some pluto logs:

Dec 13 06:25:08.284634: "tunnel-1" #15: dropping unexpected CREATE_CHILD_SA
message containing CHILD_SA_NOT_FOUND notification; message payloads: SK;
encrypted payloads: N; missing payloads: SA,Ni,TSi,TSr
Dec 13 06:25:08.785291: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I:
retransmission; will wait 0.5 seconds for response
Dec 13 06:25:08.785571: "tunnel-1" #6: responding to AUTH message (ID 1)
from 123.123.123.123:500 with encrypted notification INVALID_IKE_SPI
Dec 13 06:25:09.286236: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I:
retransmission; will wait 1 seconds for response
Dec 13 06:25:09.286536: "tunnel-1" #6: responding to AUTH message (ID 1)
from 123.123.123.123:500 with encrypted notification INVALID_IKE_SPI
Dec 13 06:25:10.287690: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I:
retransmission; will wait 2 seconds for response
Dec 13 06:25:10.287943: "tunnel-1" #6: responding to AUTH message (ID 1)
from 123.123.123.123:500 with encrypted notification INVALID_IKE_SPI
Dec 13 06:25:12.290077: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I:
retransmission; will wait 4 seconds for response
Dec 13 06:25:12.290326: "tunnel-1" #6: responding to AUTH message (ID 1)
from 123.123.123.123:500 with encrypted notification INVALID_IKE_SPI
Dec 13 06:25:16.294073: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I:
retransmission; will wait 8 seconds for response
Dec 13 06:25:16.294314: "tunnel-1" #6: responding to AUTH message (ID 1)
from 123.123.123.123:500 with encrypted notification INVALID_IKE_SPI
Dec 13 06:25:17.258577: "tunnel-1" #2: constructed local ESP/AH proposals
for tunnel-1 (ESP/AH responder matching remote proposals):
1:ESP:ENCR=AES_GCM_C_128;INTEG=NONE;DH=MODP2048;ESN=DISABLED
Dec 13 06:25:17.258605: "tunnel-1" #2: proposal
1:ESP:SPI=c6c4c3ec;ENCR=AES_GCM_C_128;DH=MODP2048;ESN=DISABLED chosen from
remote proposals
1:ESP:ENCR=AES_GCM_C_128;DH=MODP2048;ESN=DISABLED[first-match]
Dec 13 06:25:17.258615: "tunnel-1" #2: you no such IPsec SA to rekey
SA(0x19991e16) Protocol PROTO_v2_ESP
Dec 13 06:25:17.258618: "tunnel-1" #2: no valid IPsec SA SPI to rekey
Dec 13 06:25:17.258624: "tunnel-1" #16: responding to CREATE_CHILD_SA
message (ID 0) from 123.123.123.123:500 with encrypted notification
CHILD_SA_NOT_FOUND
Dec 13 06:25:24.295735: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I:
retransmission; will wait 16 seconds for response
Dec 13 06:25:24.296023: "tunnel-1" #6: responding to AUTH message (ID 1)
from 123.123.123.123:500 with encrypted notification INVALID_IKE_SPI
Dec 13 06:25:40.296797: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I:
retransmission; will wait 32 seconds for response
Dec 13 06:25:40.297050: "tunnel-1" #6: responding to AUTH message (ID 1)
from 123.123.123.123:500 with encrypted notification INVALID_IKE_SPI
Dec 13 06:26:12.301328: "tunnel-1" #15: STATE_V2_REKEY_CHILD_I: 60 second
timeout exceeded after 7 retransmits.  No response (or no acceptable
response) to our IKEv2 message
Dec 13 06:26:12.301374: "tunnel-1" #15: starting keying attempt 2 of an
unlimited number
Dec 13 06:26:12.301420: "tunnel-1" #19: constructed local ESP/AH proposals
for tunnel-1 (ESP/AH initiator emitting proposals):
1:ESP:ENCR=AES_GCM_C_128;INTEG=NONE;DH=MODP2048;ESN=DISABLED
Dec 13 06:26:12.301439: "tunnel-1" #15: deleting state
(STATE_V2_REKEY_CHILD_I) and NOT sending notification
Dec 13 06:26:12.302464: "tunnel-1" #19: message id deadlock? wait sending,
add to send next list using parent #6 unacknowledged 1 next message id=1
ike exchange window 1
Dec 13 06:28:37.261774: "tunnel-1" #16: deleting state
(STATE_V2_REKEY_CHILD_R) and NOT sending notification
Dec 13 06:28:37.261865: "tunnel-1" #16: ERROR: netlink response for Del SA
esp.c6c4c3ec at 123.123.123.123 included errno 3: No such process
Dec 13 06:28:37.261880: "tunnel-1" #16: ERROR: netlink response for Del SA
esp.0 at 345.345.345.345 included errno 3: No such process
Dec 13 06:29:32.305884: "tunnel-1" #19: deleting state (STATE_V2_CREATE_I0)
and NOT sending notification
Dec 13 06:36:49.233805: "tunnel-1" #23: constructed local ESP/AH proposals
for tunnel-1 (ESP/AH initiator emitting proposals):
1:ESP:ENCR=AES_GCM_C_128;INTEG=NONE;DH=MODP2048;ESN=DISABLED
Dec 13 06:36:49.234636: "tunnel-1" #23: message id deadlock? wait sending,
add to send next list using parent #6 unacknowledged 1 next message id=1
ike exchange window 1
Dec 13 06:40:09.236331: "tunnel-1" #25: constructed local ESP/AH proposals
for tunnel-1 (ESP/AH initiator emitting proposals):
1:ESP:ENCR=AES_GCM_C_128;INTEG=NONE;DH=MODP2048;ESN=DISABLED
Dec 13 06:40:09.236372: "tunnel-1" #23: deleting state
(STATE_V2_REKEY_CHILD_I0) and NOT sending notification
Dec 13 06:40:09.237223: "tunnel-1" #25: message id deadlock? wait sending,
add to send next list using parent #6 unacknowledged 1 next message id=1
ike exchange window 1
Dec 13 06:41:19.234277: "tunnel-1" #2: received Delete SA payload: expire
IPSEC State #7 now
Dec 13 06:41:19.234352: "tunnel-1" #8: deleting state (STATE_V2_IPSEC_R)
and sending notification
Dec 13 06:41:19.234379: "tunnel-1" #8: ESP traffic information: in=1MB
out=4MB
Dec 13 06:41:19.234487: "tunnel-1" #7: deleting state (STATE_V2_IPSEC_I)
and NOT sending notification
Dec 13 06:41:19.234502: "tunnel-1" #7: ESP traffic information: in=4MB
out=1MB
Dec 13 06:41:19.242404: expire unused parent SA #2 "tunnel-1"
Dec 13 06:41:19.242480: "tunnel-1" #6: received delete request for
PROTO_v2_ESP SA(0x19991e16) but corresponding state not found
Dec 13 06:41:19.242498: "tunnel-1" #2: ISAKMP SA expired (LATEST!)
Dec 13 06:41:19.242503: "tunnel-1" #2: deleting state (STATE_PARENT_I3) and
sending notification
Dec 13 06:41:19.243102: "tunnel-1" #25: deleting other state #25
(STATE_CHILDSA_DEL) and NOT sending notification
Dec 13 06:41:19.243184: "tunnel-1" #6: deleting state (STATE_IKESA_DEL) and
NOT sending notification

Thank you for the help in advance!

- CJ
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20181213/a41a3539/attachment.html>