[strongSwan] Lot of "rekeying active" states
Emeric POUPON
emeric.poupon at stormshield.eu
Thu Jan 12 14:07:21 CET 2017
Hello,
I have some troubles with a "rekeying active" state reported by "ipsec statusall", using strongSwan 5.2.2, on FreeBSD 10.3
I have 8 connections from a site A to a site B. Since the remote site is the same, charon picks the first one as a "parent" connection
I use uniquedids=no in the configuration, rekeying and reauth are set to default values (yes)
A lot of bidirectional traffic is being emitted from the left subnets to the right subnets.
After a while, charon ends up with several IKE SA for the parent connections, and several CHILD SA for each child connection.
This is a problem since the actual number of IKE SA / CHILD SA keeps growing over time, but that does not seem to lead to packet loss.
However, I see a lot of CHILD SA in a "rekeying active" state.
The SPI of the CHILD SA involved are no longer in the kernel, but there are in the charon internal tables.
Here is what I see:
SiteB{7}: INSTALLED, TUNNEL, ESP SPIs: c7e9e260_i c50e68eb_o
SiteB{7}: AES_CBC_256/HMAC_SHA2_256_128, 0 bytes_i, 0 bytes_o, rekeying active
SiteB{7}: 11.29.0.25/32=== 11.29.0.26/32
I reproduced this using quite short lifetimes (IKE SA : 1000s, CHILD SA : 300s)
In the log (I skip the useless creation part):
...
Jan 12 13:37:16 11[KNL] received an SADB_EXPIRE
Jan 12 13:37:16 11[KNL] creating rekey job for ESP CHILD_SA with SPI c50e68eb and reqid {8}
Jan 12 13:37:16 04[JOB] watcher got notification, rebuilding
Jan 12 13:37:16 15[MGR] checkout IKE_SA by ID
Jan 12 13:37:16 04[JOB] watcher going to poll() 5 fds
Jan 12 13:37:16 15[MGR] IKE_SA SiteB[38] successfully checked out
Jan 12 13:37:16 15[IKE] SiteB|38> queueing CHILD_REKEY task
Jan 12 13:37:16 15[IKE] SiteB|38> activating new tasks
Jan 12 13:37:16 15[IKE] SiteB|38> activating CHILD_REKEY task
Jan 12 13:37:16 15[ENC] SiteB|38> order payloads in message
Jan 12 13:37:16 15[ENC] SiteB|38> generating INFORMATIONAL request 3 [ ]
Jan 12 13:37:16 15[ENC] SiteB|38> generating payload of type HEADER
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 0 IKE_SPI
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 1 IKE_SPI
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 2 U_INT_8
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 3 U_INT_4
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 4 U_INT_4
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 5 U_INT_8
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 6 RESERVED_BIT
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 7 RESERVED_BIT
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 8 FLAG
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 9 FLAG
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 10 FLAG
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 11 FLAG
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 12 FLAG
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 13 FLAG
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 14 U_INT_32
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 15 HEADER_LENGTH
Jan 12 13:37:16 15[ENC] SiteB|38> generating HEADER payload finished
Jan 12 13:37:16 15[ENC] SiteB|38> generating payload of type ENCRYPTED
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 0 U_INT_8
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 1 U_INT_8
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 2 PAYLOAD_LENGTH
Jan 12 13:37:16 15[ENC] SiteB|38> generating rule 3 CHUNK_DATA
Jan 12 13:37:16 15[ENC] SiteB|38> generating ENCRYPTED payload finished
Jan 12 13:37:16 15[NET] SiteB|38> sending packet: from 1.51.0.1[500] to 1.51.0.2[500] (80 bytes)
Jan 12 13:37:16 15[MGR] SiteB|38> checkin IKE_SA SiteB[38]
Jan 12 13:37:16 01[JOB] next event in 800ms, waiting
Jan 12 13:37:16 12[NET] sending packet: from 1.51.0.1[500] to 1.51.0.2[500]
Jan 12 13:37:16 15[MGR] SiteB|38> check-in of IKE_SA successful.
Jan 12 13:37:16 14[NET] received packet: from 1.51.0.2[500] to 1.51.0.1[500]
Jan 12 13:37:16 14[ENC] parsing header of message
Jan 12 13:37:16 14[ENC] parsing HEADER payload, 80 bytes left
Jan 12 13:37:16 14[ENC] parsing rule 0 IKE_SPI
Jan 12 13:37:16 14[ENC] parsing rule 1 IKE_SPI
Jan 12 13:37:16 14[ENC] parsing rule 2 U_INT_8
Jan 12 13:37:16 14[ENC] parsing rule 3 U_INT_4
Jan 12 13:37:16 14[ENC] parsing rule 4 U_INT_4
Jan 12 13:37:16 14[ENC] parsing rule 5 U_INT_8
Jan 12 13:37:16 14[ENC] parsing rule 6 RESERVED_BIT
Jan 12 13:37:16 14[ENC] parsing rule 7 RESERVED_BIT
Jan 12 13:37:16 14[ENC] parsing rule 8 FLAG
Jan 12 13:37:16 14[ENC] parsing rule 9 FLAG
Jan 12 13:37:16 14[ENC] parsing rule 10 FLAG
Jan 12 13:37:16 14[ENC] parsing rule 11 FLAG
Jan 12 13:37:16 14[ENC] parsing rule 12 FLAG
Jan 12 13:37:16 14[ENC] parsing rule 13 FLAG
Jan 12 13:37:16 14[ENC] parsing rule 14 U_INT_32
Jan 12 13:37:16 14[ENC] parsing rule 15 HEADER_LENGTH
Jan 12 13:37:16 14[ENC] parsing HEADER payload finished
Jan 12 13:37:16 14[ENC] parsed a INFORMATIONAL response header
Jan 12 13:37:16 14[NET] waiting for data on sockets
Jan 12 13:37:16 16[MGR] checkout IKE_SA by message
Jan 12 13:37:16 16[MGR] IKE_SA SiteB[38] successfully checked out
Jan 12 13:37:16 16[NET] SiteB|38> received packet: from 1.51.0.2[500] to 1.51.0.1[500] (80 bytes)
Jan 12 13:37:16 16[ENC] SiteB|38> parsing body of message, first payload is ENCRYPTED
Jan 12 13:37:16 16[ENC] SiteB|38> starting parsing a ENCRYPTED payload
Jan 12 13:37:16 16[ENC] SiteB|38> parsing ENCRYPTED payload, 52 bytes left
Jan 12 13:37:16 16[ENC] SiteB|38> parsing rule 0 U_INT_8
Jan 12 13:37:16 16[ENC] SiteB|38> parsing rule 1 U_INT_8
Jan 12 13:37:16 16[ENC] SiteB|38> parsing rule 2 PAYLOAD_LENGTH
Jan 12 13:37:16 16[ENC] SiteB|38> parsing rule 3 CHUNK_DATA
Jan 12 13:37:16 16[ENC] SiteB|38> parsing ENCRYPTED payload finished
Jan 12 13:37:16 16[ENC] SiteB|38> verifying payload of type ENCRYPTED
Jan 12 13:37:16 16[ENC] SiteB|38> ENCRYPTED payload verified, adding to payload list
Jan 12 13:37:16 16[ENC] SiteB|38> ENCRYPTED payload found, stop parsing
Jan 12 13:37:16 16[ENC] SiteB|38> process payload of type ENCRYPTED
Jan 12 13:37:16 16[ENC] SiteB|38> found an encrypted payload
Jan 12 13:37:16 16[ENC] SiteB|38> parsed content of encrypted payload
Jan 12 13:37:16 16[ENC] SiteB|38> verifying message structure
Jan 12 13:37:16 16[ENC] SiteB|38> parsed INFORMATIONAL response 3 [ ]
Jan 12 13:37:16 16[IKE] SiteB|38> activating new tasks
Jan 12 13:37:16 16[IKE] SiteB|38> nothing to initiate
Jan 12 13:37:16 16[MGR] SiteB|38> checkin IKE_SA SiteB[38]
Jan 12 13:37:16 16[MGR] SiteB|38> check-in of IKE_SA successful.
...
Instead of a rekeying message, an informational message is being sent.
I can see this in the code:
--------------------
./libcharon/sa/ikev2/tasks/child_rekey.c in build_:
this->child_sa = this->ike_sa->get_child_sa(this->ike_sa, this->protocol,
this->spi, TRUE);
if (!this->child_sa)
{ /* check if it is an outbound CHILD_SA */
this->child_sa = this->ike_sa->get_child_sa(this->ike_sa, this->protocol,
this->spi, FALSE);
if (!this->child_sa)
{ /* CHILD_SA is gone, unable to rekey. As an empty CREATE_CHILD_SA
* exchange is invalid, we fall back to an INFORMATIONAL exchange.*/
message->set_exchange_type(message, INFORMATIONAL);
return SUCCESS;
}
--------------------
Some time later:
Jan 12 13:39:19 06[KNL] creating delete job for ESP CHILD_SA with SPI c50e68eb and reqid {8}
Jan 12 13:39:19 08[MGR] checkout IKE_SA by ID
Jan 12 13:39:19 04[JOB] watcher got notification, rebuilding
Jan 12 13:39:19 08[MGR] IKE_SA SiteB[38] successfully checked out
Jan 12 13:39:19 04[JOB] watcher going to poll() 5 fds
Jan 12 13:39:19 08[IKE] <SiteB|38> queueing CHILD_DELETE task
Jan 12 13:39:19 08[IKE] <SiteB|38> activating new tasks
Jan 12 13:39:19 08[IKE] <SiteB|38> activating CHILD_DELETE task
Jan 12 13:39:19 08[ENC] <SiteB|38> order payloads in message
Jan 12 13:39:19 08[ENC] <SiteB|38> generating INFORMATIONAL request 9 [ ]
Jan 12 13:39:19 08[ENC] <SiteB|38> generating payload of type HEADER
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 0 IKE_SPI
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 1 IKE_SPI
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 2 U_INT_8
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 3 U_INT_4
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 4 U_INT_4
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 5 U_INT_8
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 6 RESERVED_BIT
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 7 RESERVED_BIT
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 8 FLAG
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 9 FLAG
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 10 FLAG
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 11 FLAG
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 12 FLAG
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 13 FLAG
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 14 U_INT_32
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 15 HEADER_LENGTH
Jan 12 13:39:19 08[ENC] <SiteB|38> generating HEADER payload finished
Jan 12 13:39:19 08[ENC] <SiteB|38> generating payload of type ENCRYPTED
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 0 U_INT_8
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 1 U_INT_8
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 2 PAYLOAD_LENGTH
Jan 12 13:39:19 08[ENC] <SiteB|38> generating rule 3 CHUNK_DATA
Jan 12 13:39:19 08[ENC] <SiteB|38> generating ENCRYPTED payload finished
Jan 12 13:39:19 08[NET] <SiteB|38> sending packet: from 1.51.0.1[500] to 1.51.0.2[500] (80 bytes)
Jan 12 13:39:19 08[MGR] <SiteB|38> checkin IKE_SA SiteB[38]
Jan 12 13:39:19 01[JOB] next event in 910ms, waiting
Jan 12 13:39:19 12[NET] sending packet: from 1.51.0.1[500] to 1.51.0.2[500]
Jan 12 13:39:19 08[MGR] <SiteB|38> check-in of IKE_SA successful.
Jan 12 13:39:19 14[NET] received packet: from 1.51.0.2[500] to 1.51.0.1[500]
Jan 12 13:39:19 14[ENC] parsing header of message
Jan 12 13:39:19 14[ENC] parsing HEADER payload, 80 bytes left
Jan 12 13:39:19 14[ENC] parsing rule 0 IKE_SPI
Jan 12 13:39:19 14[ENC] parsing rule 1 IKE_SPI
Jan 12 13:39:19 14[ENC] parsing rule 2 U_INT_8
Jan 12 13:39:19 14[ENC] parsing rule 3 U_INT_4
Jan 12 13:39:19 14[ENC] parsing rule 4 U_INT_4
Jan 12 13:39:19 14[ENC] parsing rule 5 U_INT_8
Jan 12 13:39:19 14[ENC] parsing rule 6 RESERVED_BIT
Jan 12 13:39:19 14[ENC] parsing rule 7 RESERVED_BIT
Jan 12 13:39:19 14[ENC] parsing rule 8 FLAG
Jan 12 13:39:19 14[ENC] parsing rule 9 FLAG
Jan 12 13:39:19 14[ENC] parsing rule 10 FLAG
Jan 12 13:39:19 14[ENC] parsing rule 11 FLAG
Jan 12 13:39:19 14[ENC] parsing rule 12 FLAG
Jan 12 13:39:19 14[ENC] parsing rule 13 FLAG
Jan 12 13:39:19 14[ENC] parsing rule 14 U_INT_32
Jan 12 13:39:19 14[ENC] parsing rule 15 HEADER_LENGTH
Jan 12 13:39:19 14[ENC] parsing HEADER payload finished
Jan 12 13:39:19 14[ENC] parsed a INFORMATIONAL response header
Jan 12 13:39:19 14[NET] waiting for data on sockets
Jan 12 13:39:19 15[MGR] checkout IKE_SA by message
Jan 12 13:39:19 15[MGR] IKE_SA SiteB[38] successfully checked out
Jan 12 13:39:19 15[NET] <SiteB|38> received packet: from 1.51.0.2[500] to 1.51.0.1[500] (80 bytes)
Jan 12 13:39:19 15[ENC] <SiteB|38> parsing body of message, first payload is ENCRYPTED
Jan 12 13:39:19 15[ENC] <SiteB|38> starting parsing a ENCRYPTED payload
Jan 12 13:39:19 15[ENC] <SiteB|38> parsing ENCRYPTED payload, 52 bytes left
Jan 12 13:39:19 15[ENC] <SiteB|38> parsing rule 0 U_INT_8
Jan 12 13:39:19 15[ENC] <SiteB|38> parsing rule 1 U_INT_8
Jan 12 13:39:19 15[ENC] <SiteB|38> parsing rule 2 PAYLOAD_LENGTH
Jan 12 13:39:19 15[ENC] <SiteB|38> parsing rule 3 CHUNK_DATA
Jan 12 13:39:19 15[ENC] <SiteB|38> parsing ENCRYPTED payload finished
Jan 12 13:39:19 15[ENC] <SiteB|38> verifying payload of type ENCRYPTED
Jan 12 13:39:19 15[ENC] <SiteB|38> ENCRYPTED payload verified, adding to payload list
Jan 12 13:39:19 15[ENC] <SiteB|38> ENCRYPTED payload found, stop parsing
Jan 12 13:39:19 15[ENC] <SiteB|38> process payload of type ENCRYPTED
Jan 12 13:39:19 15[ENC] <SiteB|38> found an encrypted payload
Jan 12 13:39:19 15[ENC] <SiteB|38> parsed content of encrypted payload
Jan 12 13:39:19 15[ENC] <SiteB|38> verifying message structure
Jan 12 13:39:19 15[ENC] <SiteB|38> parsed INFORMATIONAL response 9 [ ]
Jan 12 13:39:19 15[IKE] <SiteB|38> activating new tasks
Jan 12 13:39:19 15[IKE] <SiteB|38> nothing to initiate
Jan 12 13:39:19 15[MGR] <SiteB|38> checkin IKE_SA SiteB[38]
Jan 12 13:39:19 15[MGR] <SiteB|38> check-in of IKE_SA successful.
And then nothing happens.
When a I type in "ipsec statusall" I get this:
...
Jan 12 13:40:18 16[KNL] SiteB|37> querying SAD entry with SPI c50e68eb
Jan 12 13:40:18 16[KNL] SiteB|37> unable to query SAD entry with SPI c50e68eb: No such file or directory (2)
...
The CHILD SA is later flushed when the IKE SA is being deleted.
...
Jan 12 13:42:27 06[IKE] SiteB|37> IKE_SA SiteB[37] state change: DELETING => DESTROYING
...
Jan 12 13:42:27 06[KNL] SiteB|37> deleting SAD entry with SPI c50e68eb
Jan 12 13:42:27 06[KNL] SiteB|37> unable to delete SAD entry with SPI c50e68eb: No such file or directory (2)
...
Why does the SA is not being rekeyed? This sounds like a bug.
What do you think?
Emeric
More information about the Users
mailing list