On Mon, 15 Sep 2025, Erik Thuning via openssh-unix-dev wrote:
> Hi!
>
> I was debugging what I thought to be an exotic new failure mode in ssh last
> week, with the following being the only hints in the auth log to go on:
>
> 2025-09-08T20:41:17.233159+02:00 servername sshd-session[884433]:
Connection
> closed by some.client.ip port 39200 [preauth]
> 2025-09-08T20:41:17.356525+02:00 servername sshd-session[884435]:
Connection
> closed by some.client.ip port 39204 [preauth]
> 2025-09-08T20:41:17.481084+02:00 servername sshd-session[884437]:
Connection
> closed by some.client.ip port 39220 [preauth]
> 2025-09-08T20:41:17.503513+02:00 servername sshd-session[884438]: Unable to
> negotiate with some.client.ip port 39222: no matching host key type found.
> Their offer: sk-ecdsa-sha2-nistp256 at openssh.com [preauth]
> 2025-09-08T20:41:17.528975+02:00 servername sshd-session[884439]: Unable to
> negotiate with some.client.ip port 39224: no matching host key type found.
> Their offer: sk-ssh-ed25519 at openssh.com [preauth]
>
>
> When I turned on debug logging, I could immediately see that the issue was
the
> new penalisation feature (which I didn't even know existed, but
that's on me).
> What catches my eye here though is this:
>
> 2025-09-11T15:20:19.768262+02:00 servername sshd[1599576]: debug1:
> srclimit_penalise: inactive penalty for ipv4 redacted.client.ip/32 already
> exists, 14 seconds remaining
> 2025-09-11T15:20:19.768299+02:00 servername sshd[1599576]:
srclimit_penalise:
> redacted.client.ip/32: activating ipv4 penalty of 19 seconds for penalty:
> failed authentication
>
>
> The first line is obviously printed at debug1 level, and that's fine.
The
> second line isn't tagged debug though, so since we normally log at
INFO, I
> assume it's from VERBOSE.
>
> Now, my question is why penalisation of clients isn't logged at INFO
level? Is
> it to reduce log spam? It would certainly be helpful from a debugging
> perspective to see when a client is penalised, so if there is no indication
at
> the default log level, is there some way of listing currently active
> penalties? I'm not seeing anything to that effect in the manual.
Yeah, it's to avoid logspam. Maybe we could be more nuanced. Does this
help? It logs penalties at the default level when they become active.
diff --git a/srclimit.c b/srclimit.c
index 8a47588e4..c62763724 100644
--- a/srclimit.c
+++ b/srclimit.c
@@ -427,7 +427,9 @@ srclimit_penalise(struct xaddr *addr, int penalty_type)
penalty->active = 1;
if (RB_INSERT(penalties_by_expiry, by_expiry, penalty) != NULL)
fatal_f("internal error: %s penalty tables corrupt", t);
- verbose_f("%s: new %s %s penalty of %d seconds for %s", t,
+ do_log2_f(penalty->active ?
+ SYSLOG_LEVEL_INFO : SYSLOG_LEVEL_VERBOSE,
+ "%s: new %s %s penalty of %d seconds for %s", t,
addrnetmask, penalty->active ? "active" :
"deferred",
penalty_secs, reason);
if (++(*npenaltiesp) > (size_t)max_sources)
@@ -446,7 +448,7 @@ srclimit_penalise(struct xaddr *addr, int penalty_type)
existing->expiry = now + penalty_cfg.penalty_max;
if (existing->expiry - now > penalty_cfg.penalty_min &&
!existing->active) {
- verbose_f("%s: activating %s penalty of %lld seconds for %s",
+ logit_f("%s: activating %s penalty of %lld seconds for %s",
addrnetmask, t, (long long)(existing->expiry - now),
reason);
existing->active = 1;