[Swan-dev] Bogus "established IKE SA" messages

[Andrew Cagney]

On Mon, 5 Apr 2021 at 19:03, Paul Wouters <paul at nohats.ca> wrote:

>
> Eg see this log:
>
> Apr  5 18:56:32.909849: "west" #4: sent CREATE_CHILD_SA request to rekey
> IPsec SA
> Apr  5 18:56:32.917812: "west" #4: rekeyed #3 STATE_V2_REKEY_CHILD_I1 and
> expire it remaining life 28774.21038s
> Apr  5 18:56:32.917920: "west" #4: negotiated connection
> [192.0.1.0-192.0.1.255:0-65535 0] -> [192.0.2.0-192.0.2.255:0-65535 0]
> Apr  5 18:56:32.917928: "west" #4: IPsec SA established tunnel mode
> {ESP=>0x19ae6dab <0x0ec6e523 xfrm=AES_GCM_16_256-NONE-MODP2048 NATOA=none
> NATD=none DPD=passive}
> Apr  5 18:56:33.918801: "west" #3: deleting state
> (STATE_V2_ESTABLISHED_CHILD_SA) aged 26.826433s and sending notification
> Apr  5 18:56:33.918917: "west" #3: ESP traffic information: in=1KB out=1KB
> Apr  5 18:56:33.921937: "west" #1: received delete request for
> IKEv2_SEC_PROTO_ESP SA(0xfe024578) but corresponding state not found
> Apr  5 18:56:33.922055: "west" #1: established IKE SA
> Apr  5 18:56:46.640199: "west" #1: received Delete SA payload: replace
> CHILD SA #4 now
> Apr  5 18:56:46.640351: "west" #1: established IKE SA
>
> The only event here was a CREATE_CHILD_SA for a Child SA. it should not
> print those "established IKE SA" messages.
>

It's connected to:

         * Tell whack and logs our progress - unless OE or a state
         * transition we're not telling anyone about, then be quiet.
         *
         * XXX: This code uses the new state, and not the state
         * transition to determine if things established :-(
         *
         * This should be a bit in the transition!

although the comment is slightly out-of-date.  The bit
SMF2_SUPPRESS_SUCCESS_LOG has been added (more are needed).  You could try
adding it to this transition:

        { .story      = "Informational Request",
          .state      = STATE_V2_ESTABLISHED_IKE_SA,
          .next_state = STATE_V2_ESTABLISHED_IKE_SA,
          .send       = MESSAGE_RESPONSE,
          .req_clear_payloads = P(SK),
          .opt_enc_payloads = P(N) | P(D) | P(CP),
          .processor  = process_encrypted_informational_ikev2,
          .recv_role  = MESSAGE_REQUEST,
          .recv_type  = ISAKMP_v2_INFORMATIONAL,
          .timeout_event = EVENT_RETAIN, },


> Also, I wonder if we should keep a recent list of deleted IPsec and
> IKE SPI's, so when we get a delete response for something we have just
> deleted, we don't show a weird "not found" error.
>
>
As in two delete requests crossing in the night?

Could this be from the delete code being a little too aggressive - deleting
the incoming channel before the delete response has been received?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan-dev/attachments/20210405/4008fcd6/attachment-0001.html>