Mailing List Archive

On Tue, 21 Jan 2020, Craig Miskell wrote:

> Hi,
>
> We serve a fairly substantial number[1] of ssh connections across our
> fleet.  We have hit MaxStartups limits in the past and bumped it up a
> few times (currently at 300), but we have no warning before the limit is
> reached and connections start being dropped.  What I would love is some
> sort of instrumentation that could let us see the highest number of
> concurrent pre-auth connections the current running instance of the
> daemon has seen, so we can graph it and alert on it pro-actively (e.g.
> when we get within some reasonable percentage of the actual limit), and
> then decide if we need to increase MaxStartups further, scale our fleet
> horizontally, or do something else.
>
> I'm more than happy to write & contribute the code to do this
> instrumentation, but I'd like to get some guidance on
> direction/implementation options first, so I don't spend time writing
> code which is never going to be accepted.
>
> The most trivial approach would be to add logging to the main daemon,
> either when we get within X% of MaxStartups (X being possibly
> configurable), or just log the current max value every X minutes or Y
> connections (perhaps at Verbose logging level?). Either would be
> functional, but both feel a little bit unwieldy.

It would be trivial to make sshd.c:drop_connection() log a little more,
e.g. when the number of authenticating connections exceeds say 50% of
MaxStartups.

> Alternatively, we could go a more complex and flexible route such as the
> way haproxy does it, with a local unix socket that responds to a 'stats'
> command with some simple text format.  This would be more generally
> usable and extensible to other metrics in future, and seems more robust
> to me, although would be a more noticeable amount of work than just logging.

I'm reticent to add more interfaces to the sshd listener, especially ones
that accept any sort of command. The sshd listener has to be reliable
and (IMO) as simple as possible. Maybe some write-only interface where
sshd can dump stats could be simple enough?

There aren't many stats to dump ATM though, just the active number of
startups - everything else of potential interest is in separate forked
sshd processes where they aren't accessible without quite a lot of work.

This makes me think that the syslog approach is probably the way to go
unless someone can come up with other stuff that would be a) worth reading
and b) accessible.

-d

_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev

> This makes me think that the syslog approach is probably the way to go

Yeah, right.
Another idea is to mirror the current preauth load via setproctitle()...
That makes that data accessible even without a syscall (at least the
writing of the data - quering needs syscalls, right), so that can be
kept up-to-date and allows a high monitoring frequency as well.

Multiple instances of SSHd (on different ports) are easily distinguished
as well.


> unless someone can come up with other stuff that would be a) worth
> reading
> and b) accessible.

Data that I would like to see logged is the utime information of child
processes - how much user/sys time the processes took, memory usage,
and some more.

I imagine a single-line output with SSHd pid, session ID, user,
child PID, and the accounting data - that would be nice to have.


The parallel ongoing discussion about ControlMaster reminds me that
one SSH connection might drop multiple such log lines...
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev

On Tue, 21 Jan 2020, Philipp Marek wrote:

> > This makes me think that the syslog approach is probably the way to go
>
> Yeah, right.
> Another idea is to mirror the current preauth load via setproctitle()...
> That makes that data accessible even without a syscall (at least the
> writing of the data - quering needs syscalls, right), so that can be
> kept up-to-date and allows a high monitoring frequency as well.
>
> Multiple instances of SSHd (on different ports) are easily distinguished
> as well.

That's a really, really good idea. Patch below.

> Data that I would like to see logged is the utime information of child
> processes - how much user/sys time the processes took, memory usage,
> and some more.
>
> I imagine a single-line output with SSHd pid, session ID, user,
> child PID, and the accounting data - that would be nice to have.
>
> The parallel ongoing discussion about ControlMaster reminds me that
> one SSH connection might drop multiple such log lines...

Well, there's two plausible places where this could be logged:

1) At shell/command termination. This would be a little divorced from its
context however, because we don't log any commands for privacy reasons.
2) At connection termination; this would roll up all stats for multiplexed
sessions as you observe.

-d

diff --git a/sshd.c b/sshd.c
index 6129b0a..debbdcb 100644
--- a/sshd.c
+++ b/sshd.c
@@ -1005,7 +1005,7 @@ server_accept_loop(int *sock_in, int *sock_out, int *newsock, int *config_s)
{
fd_set *fdset;
int i, j, ret, maxfd;
- int startups = 0, listening = 0, lameduck = 0;
+ int ostartups = -1, startups = 0, listening = 0, lameduck = 0;
int startup_p[2] = { -1 , -1 };
char c = 0;
struct sockaddr_storage from;
@@ -1029,6 +1029,11 @@ server_accept_loop(int *sock_in, int *sock_out, int *newsock, int *config_s)
* the daemon is killed with a signal.
*/
for (;;) {
+ if (ostartups != startups) {
+ setproctitle("[listener] %d/%d startups",
+ startups, options.max_startups);
+ ostartups = startups;
+ }
if (received_sighup) {
if (!lameduck) {
debug("Received SIGHUP; waiting for children");
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev

>> Another idea is to mirror the current preauth load via
>> setproctitle()...
...
> That's a really, really good idea. Patch below.
Thanks ;)


>> Data that I would like to see logged is the utime information of child
>> processes - how much user/sys time the processes took, memory usage,
>> and some more.
...
> Well, there's two plausible places where this could be logged:
>
> 1) At shell/command termination. This would be a little divorced from
> its
> context however, because we don't log any commands for privacy
> reasons.
> 2) At connection termination; this would roll up all stats for
> multiplexed
> sessions as you observe.

No, that's too late for my use case.

A ControlMaster might be active for multiple days, weeks, or (hopefully)
even months ;)
At least until the next update, that is.


For multiplexed connections every one of them needs to be logged
separately - I understand that the command isn't logged, but if the PID
is included then the command itself (which probably is just a script)
can log its PID, the audit log can be used, or (in the worst case)
SystemTap or some similar stuff can be used.

Mostly, "resources spent per user" would be interesting.

_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev

On 21/01/20 8:44 pm, Damien Miller wrote:
> On Tue, 21 Jan 2020, Philipp Marek wrote:
>
>>> This makes me think that the syslog approach is probably the way to go
>>
>> Yeah, right.
>> Another idea is to mirror the current preauth load via setproctitle()...
>> That makes that data accessible even without a syscall (at least the
>> writing of the data - quering needs syscalls, right), so that can be
>> kept up-to-date and allows a high monitoring frequency as well.
>>
>> Multiple instances of SSHd (on different ports) are easily distinguished
>> as well.
>
> That's a really, really good idea. Patch below.

That would certainly cover my use case. I wonder if there's a case to
be made to add options.max_startups_begin to the title status (per the
amended patch below). It's more informative, but also a bit more
confusing e.g. when we're above max_startups_begin and beginning to drop
we get a title like:

sshd: [listener] 12/10/100 startups

But my primary goal here is getting that first number exposed and we
could reasonably make max_startups_begin and max_startups the same; for
us, once we start dropping any we may as well be dropping them all,
because it happening at all is a thing to be avoided, and we want
to/should have been alerted before it happens. So the original patch
would certainly be sufficient.

Just an aside: I notice that the original patch got included in commit
f8c11461aa6db168fc5e7eeae448b4cbbf59642a in the portable git repo, along
with another change that matches the commit message. Was that intentional?


-- Craig Miskell Site Reliability Engineer | GitLab | Dunedin, New Zealand

diff --git a/sshd.c b/sshd.c
index 6129b0a..debbdcb 100644
--- a/sshd.c
+++ b/sshd.c
@@ -1005,7 +1005,7 @@ server_accept_loop(int *sock_in, int *sock_out,
int *newsock, int *config_s)
{
fd_set *fdset;
int i, j, ret, maxfd;
- int startups = 0, listening = 0, lameduck = 0;
+ int ostartups = -1, startups = 0, listening = 0, lameduck = 0;
int startup_p[2] = { -1 , -1 };
char c = 0;
struct sockaddr_storage from;
@@ -1029,6 +1029,11 @@ server_accept_loop(int *sock_in, int *sock_out,
int *newsock, int *config_s)
* the daemon is killed with a signal.
*/
for (;;) {
+ if (ostartups != startups) {
+ setproctitle("[listener] %d/%d/%d startups",
+ startups, options.max_startups_begin, options.max_startups);
+ ostartups = startups;
+ }
if (received_sighup) {
if (!lameduck) {
debug("Received SIGHUP; waiting for children");
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev

On Wed, 22 Jan 2020, Craig Miskell wrote:

>
> On 21/01/20 8:44 pm, Damien Miller wrote:
> > On Tue, 21 Jan 2020, Philipp Marek wrote:
> >
> >>> This makes me think that the syslog approach is probably the way to go
> >>
> >> Yeah, right.
> >> Another idea is to mirror the current preauth load via setproctitle()...
> >> That makes that data accessible even without a syscall (at least the
> >> writing of the data - quering needs syscalls, right), so that can be
> >> kept up-to-date and allows a high monitoring frequency as well.
> >>
> >> Multiple instances of SSHd (on different ports) are easily distinguished
> >> as well.
> >
> > That's a really, really good idea. Patch below.
>
> That would certainly cover my use case. I wonder if there's a case to be made
> to add options.max_startups_begin to the title status (per the amended patch
> below). It's more informative, but also a bit more confusing e.g. when we're
> above max_startups_begin and beginning to drop we get a title like:
>
> sshd: [listener] 12/10/100 startups
>
> But my primary goal here is getting that first number exposed and we could
> reasonably make max_startups_begin and max_startups the same; for us, once we
> start dropping any we may as well be dropping them all, because it happening
> at all is a thing to be avoided, and we want to/should have been alerted
> before it happens. So the original patch would certainly be sufficient.

Thanks for the feedback. I've just committed this with the max_startups_begin
exposed:

72691 ?? I 0:00.00 sshd: [listener] 0 of 10-100 startups (sshd)

> Just an aside: I notice that the original patch got included in commit
> f8c11461aa6db168fc5e7eeae448b4cbbf59642a in the portable git repo, along with
> another change that matches the commit message. Was that intentional?

Nope, and I reverted it before I committed the final one :)

-d
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev

>> That would certainly cover my use case. I wonder if there's a case to be made
>> to add options.max_startups_begin to the title status (per the amended patch
>> below). It's more informative, but also a bit more confusing e.g. when we're
>> above max_startups_begin and beginning to drop we get a title like:
>>
>> sshd: [listener] 12/10/100 startups
>>
>> But my primary goal here is getting that first number exposed and we could
>> reasonably make max_startups_begin and max_startups the same; for us, once we
>> start dropping any we may as well be dropping them all, because it happening
>> at all is a thing to be avoided, and we want to/should have been alerted
>> before it happens. So the original patch would certainly be sufficient.
>
> Thanks for the feedback. I've just committed this with the max_startups_begin
> exposed:
>
> 72691 ?? I 0:00.00 sshd: [listener] 0 of 10-100 startups (sshd)

Magic! Thank you!

--
Craig Miskell Site Reliability Engineer | GitLab | Dunedin, New Zealand
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev