[Ipsec-tools-devel] ERROR: pfkey DELETE received

[Eugene M. Zheganin]

Hi.

I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ? Is this an error or may be it's just receiving an ISAKMP
payload delete advisory is just logged each time with the ERROR loglevel
priority ?

Thanks.
Eugene.

------------------------------------------------------------------------------

[Rainer Weikusat]

Post by Eugene M. Zheganin
Hi.
I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ?

It means racoon has received a PF_KEY SADB_DELETE message whose process
ID differed from its own, ie, one which was apparently not sent by
itself.

------------------------------------------------------------------------------

[Eugene M. Zheganin]

Hi.

Post by Rainer Weikusat

Post by Eugene M. Zheganin
Hi.
I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ?

It means racoon has received a PF_KEY SADB_DELETE message whose process
ID differed from its own, ie, one which was apparently not sent by
itself.

I took a look into the pfkey.c code, and it seems like your
interpretation is incorrect. Looks like this message is logged whenever
the pfkey DELETE is received from the remote and it has been validated,
found valid, so the appropriate SA will be deleted right now.

Eugene.

[Jaco Kroon]

Hi,

Post by Eugene M. Zheganin

Post by Rainer Weikusat

Post by Eugene M. Zheganin
Hi.
I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ?

It means racoon has received a PF_KEY SADB_DELETE message whose process
ID differed from its own, ie, one which was apparently not sent by
itself.

I took a look into the pfkey.c code, and it seems like your
interpretation is incorrect. Looks like this message is logged whenever
the pfkey DELETE is received from the remote and it has been validated,
found valid, so the appropriate SA will be deleted right now.

Then perhaps it should not be flagged as ERROR: if this is the normal
and expected behaviour?

Kind Regards,
Jaco

[Rainer Weikusat]

Post by Jaco Kroon

Post by Eugene M. Zheganin

Post by Rainer Weikusat

Post by Eugene M. Zheganin
Hi.
I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ?

It means racoon has received a PF_KEY SADB_DELETE message whose process
ID differed from its own, ie, one which was apparently not sent by
itself.

I took a look into the pfkey.c code, and it seems like your
interpretation is incorrect. Looks like this message is logged whenever
the pfkey DELETE is received from the remote and it has been validated,
found valid, so the appropriate SA will be deleted right now.

Then perhaps it should not be flagged as ERROR: if this is the normal
and expected behaviour?

"It depends". ph2 SAs managed by a certain racoon process shouldn't
usually be deleted by other processes. OTOH, it could have been flushed
manually by an admin executing some command for doing this which doesn't
go through racoon, ie, something other than racoonctl.

[Rainer Weikusat]

Post by Eugene M. Zheganin

Post by Rainer Weikusat

Post by Eugene M. Zheganin
I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ?

It means racoon has received a PF_KEY SADB_DELETE message whose process
ID differed from its own, ie, one which was apparently not sent by
itself.

I took a look into the pfkey.c code, and it seems like your
interpretation is incorrect. Looks like this message is logged whenever
the pfkey DELETE is received from the remote

pfkey delete message can't be received "from remote" because PF_KEY
sockets are only used for local message exchanges. The actual code
(0.8.2) is this:

/* the message has to be processed or not ? */
if (msg->sadb_msg_pid == getpid()) {
plog(LLV_DEBUG, LOCATION, NULL,
"%s message is not interesting "
"because the message was originated by me.\n",
s_pfkey_type(msg->sadb_msg_type));
return -1;
}

If execution goes beyond the if-block above, the pid in the message was
different from the pid of the racoon process, IOW, it was sent by some
other process.

proto_id = pfkey2ipsecdoi_proto(msg->sadb_msg_satype);
if (proto_id == ~0) {
plog(LLV_ERROR, LOCATION, NULL,
"invalid proto_id %d\n", msg->sadb_msg_satype);
return -1;
}

That's a validity check.

iph2 = getph2bysaidx(src, dst, proto_id, sa->sadb_sa_spi);
if (iph2 == NULL) {
/* ignore */
plog(LLV_ERROR, LOCATION, NULL,
"no iph2 found: %s\n",
sadbsecas2str(src, dst, msg->sadb_msg_satype,
sa->sadb_sa_spi, IPSEC_MODE_ANY));
return 0;
}

Search for a matching ph2 and return after logging a "no iph2 found"
error message if none was found.

plog(LLV_ERROR, LOCATION, NULL,
"pfkey DELETE received: %s\n",
sadbsecas2str(src, dst,
msg->sadb_msg_satype, sa->sadb_sa_spi, IPSEC_MODE_ANY));

Log the error you observed.

/* send delete information */
if (iph2->status == PHASE2ST_ESTABLISHED)
isakmp_info_send_d2(iph2);

Send an ISAKMP ph2 delete notification to the peer in case the ph2 was
established.

remph2(iph2);
delph2(iph2);

Remove the associated data structures.

[Eugene M. Zheganin]

Hi.

Post by Rainer Weikusat

Post by Eugene M. Zheganin
Hi.
I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ?

It means racoon has received a PF_KEY SADB_DELETE message whose process
ID differed from its own, ie, one which was apparently not sent by
itself.

Sorry for this grave digging, but I'm forced to reinvestigate this
issue. Given that I have in the logs a record like

May 1 19:00:02 balancer1 racoon: ERROR: pfkey DELETE received: ESP
XXX.XX.XXX.XX[500]->ZZZ.ZZ.ZZZ.ZZ[500] spi=831488614(0x318f8266)

- what can it mean ? XXX.XX.XXX.XX is a local IP of the server that
logged this message. I think the '->' represents the direction, but if
some message is "received" why the direction is outgoing ?
- if it's not the local racoon who's initiating the pfkey DELETE when
who can it be ? I'm the only engineer having access to this server. I'm
not issuing any SADB changes. I'm also not unsing any kind of
DPD-initiated scripts, which could issue such changes. Yet I'm seeing
these messages in logs. Is there any way of determining who was it ?

Thanks.
Eugene.

[Rainer Weikusat]

Post by Eugene M. Zheganin

Post by Rainer Weikusat

Post by Eugene M. Zheganin
Hi.
I'm seeing the message "ERROR: pfkey DELETE received" quite periodically
in logs. However, it does not seem it to cause any problems. What does
this mean ?

It means racoon has received a PF_KEY SADB_DELETE message whose process
ID differed from its own, ie, one which was apparently not sent by
itself.

Sorry for this grave digging, but I'm forced to reinvestigate this
issue. Given that I have in the logs a record like
May 1 19:00:02 balancer1 racoon: ERROR: pfkey DELETE received: ESP
XXX.XX.XXX.XX[500]->ZZZ.ZZ.ZZZ.ZZ[500] spi=831488614(0x318f8266)
- what can it mean ? XXX.XX.XXX.XX is a local IP of the server that
logged this message. I think the '->' represents the direction, but if
some message is "received" why the direction is outgoing ?

That's logged by this code (in pfkey.c/ pk_recvdelete)

iph2 = getph2bysaidx(src, dst, proto_id, sa->sadb_sa_spi);
if (iph2 == NULL) {
/* ignore */
plog(LLV_ERROR, LOCATION, NULL,
"no iph2 found: %s\n",
sadbsecas2str(src, dst, msg->sadb_msg_satype,
sa->sadb_sa_spi, IPSEC_MODE_ANY));
return 0;
}

plog(LLV_ERROR, LOCATION, NULL,
"pfkey DELETE received: %s\n",
sadbsecas2str(src, dst,
msg->sadb_msg_satype, sa->sadb_sa_spi, IPSEC_MODE_ANY));

The addresses represent source and destination address of the ph2 SA the
delete message referred to and the spi= is it's spi. The message is
'received' because it's a PF_KEY message (local IPsec configuration
management protocol message sent by the kernel). More to the top of this
function, you'll find the following code:


/* the message has to be processed or not ? */
if (msg->sadb_msg_pid == getpid()) {
plog(LLV_DEBUG, LOCATION, NULL,
"%s message is not interesting "
"because the message was originated by me.\n",
s_pfkey_type(msg->sadb_msg_type));
return -1;
}

Communication generally works as follows:

1. Something sends a PF_KEY delete message to the kernel. This
instructs the kernel to delete the SAs specified in the
message. That something is supposed to send its process ID as
part of the message meta-information.

2. The kernel resends the PF_KEY messages to all registered
PF_KEY listeners to inform them about the fact. A listener
can determine if the original message was sent by itself or
by some other entity by comparings its pid with the pid in
the received message (that's what the check above does).

You could change the LLV_ERROR message to include the received pid, eg,
to something like (untested)

plog(LLV_ERROR, LOCATION, NULL,
"pfkey DELETE received: %s (%u)\n",
sadbsecas2str(src, dst,
msg->sadb_msg_satype, sa->sadb_sa_spi, IPSEC_MODE_ANY), msg->sadb_msg_pid);

This would give you the process ID of the entity which sent the message
which ought to be helpful for identifying the sender of the message.

A conceivable scenario (conjecture which doesn't contradict know facts):
A racoon process sends a delete and then crashes. It's restarted
automatically and the new process receives the delete.