Re: Error reporting in ikev2_ike_sa_alive (was: Improve error reporting in pfkey_sa_last_used)

[matthew j weaver]

On Sun, May 31, 2020, at 17:27, Tobias Heider wrote:
> I don't think this is a good idea
> With your diff the log gets spammed with 'Undefined error: 0' for child SAs
> that have never been used.
> Also log_warn seems a bit too much as those errors are rarely serious.

  Thank you for having a look, Tobias. I appreciate the time & the feedback.

  Embarassed I didn't test the unused child SA case.

  I'll come back around if I think of a more elegant way to expose debug for 
the case here that's interesting.

  matthew weaver

Re: Error reporting in ikev2_ike_sa_alive (was: Improve error reporting in pfkey_sa_last_used)

[Tobias Heider]

On Tue, May 26, 2020 at 12:08:08PM -0400, matthew j weaver wrote:
> During childsa last use checks, iked debug logs results, per SA, after a
> successful pfkey_sa_last_used call.
> 
> This patch makes logging behavior more closely match that, on error.
> 
> I chose log_warn instead of log_debug since iked will complain about the
> nonzero errno after pfkey_reply:
>   pfkey_sa_last_used: message: No such process
> 
> With this patch an operator can at least troubleshoot which SAs are
> causing the trouble.
> 
> Comments? Make sense?
> 
> thank you, all
> matthew weaver

I don't think this is a good idea
With your diff the log gets spammed with 'Undefined error: 0' for child SAs
that have never been used.
Also log_warn seems a bit too much as those errors are rarely serious.

Error reporting in ikev2_ike_sa_alive (was: Improve error reporting in pfkey_sa_last_used)

[matthew j weaver]

During childsa last use checks, iked debug logs results, per SA, after a
successful pfkey_sa_last_used call.

This patch makes logging behavior more closely match that, on error.

I chose log_warn instead of log_debug since iked will complain about the
nonzero errno after pfkey_reply:
pfkey_sa_last_used: message: No such process

With this patch an operator can at least troubleshoot which SAs are
causing the trouble.

Comments? Make sense?

thank you, all
matthew weaver

---

Index: ikev2.c
===
RCS file: /cvs/src/sbin/iked/ikev2.c,v
retrieving revision 1.223
diff -u -p -u -r1.223 ikev2.c
--- ikev2.c 2 May 2020 13:01:37 -   1.223
+++ ikev2.c 26 May 2020 15:53:42 -
@@ -4347,8 +4347,15 @@ ikev2_ike_sa_alive(struct iked *env, voi
TAILQ_FOREACH(csa, >sa_childsas, csa_entry) {
if (!csa->csa_loaded)
continue;
-   if (pfkey_sa_last_used(env->sc_pfkey, csa, _used) != 0)
+   if (pfkey_sa_last_used(env->sc_pfkey, csa, _used) != 0) {
+   log_warn(
+   "%s: %s CHILD SA spi %s failed to determine "
+   "last use", __func__,
+   csa->csa_dir == IPSP_DIRECTION_IN ?
+   "incoming" : "outgoing",
+   print_spi(csa->csa_spi.spi, csa->csa_spi.spi_size));
continue;
+   }
diff = (uint32_t)(gettime() - last_used);
log_debug("%s: %s CHILD SA spi %s last used %llu second(s) ago",
__func__,