sshd(8) logging of client disconnect from ClientAliveInterval

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

sshd(8) logging of client disconnect from ClientAliveInterval

Lars Noodén
sshd(8) used to log connection information when ClientAliveInterval
disconnected an idle client.

It used to look something like this a while back:

        Oct 16 14:42:08 eee sshd[83709]: packet_write_poll: Connection from 192.0.2.97
        port 57608: Host is down

Now it looks like this:

        Oct 16 21:18:56 eee sshd[94170]: Timeout, client not responding.

It would be very useful to have the connection information back again.
Here is a cargo-culted modification that approximates the old style.

/Lars

Index: src/usr.bin/ssh/serverloop.c
===================================================================
RCS file: /cvs/src/usr.bin/ssh/serverloop.c,v
retrieving revision 1.198
diff -u -p -u -r1.198 serverloop.c
--- src/usr.bin/ssh/serverloop.c        12 Sep 2017 06:35:32 -0000      1.198
+++ src/usr.bin/ssh/serverloop.c        16 Oct 2017 18:58:01 -0000
@@ -165,7 +165,8 @@ client_alive_check(struct ssh *ssh)

        /* timeout, check to see how many we have had */
        if (packet_inc_alive_timeouts() > options.client_alive_count_max) {
-               logit("Timeout, client not responding.");
+               logit("Timeout, client not responding from %s on port %d.",
+               ssh_remote_ipaddr(ssh), ssh_remote_port(ssh) );
                cleanup_exit(255);
        }

Reply | Threaded
Open this post in threaded view
|

Re: sshd(8) logging of client disconnect from ClientAliveInterval

Darren Tucker
On 17 October 2017 at 06:04, Lars Noodén <[hidden email]> wrote:
>
> +               logit("Timeout, client not responding from %s on port %d.",
> +               ssh_remote_ipaddr(ssh), ssh_remote_port(ssh) );
>

probably better to use fmt_connection_id() instead of hand-rolling the
format.

--
Darren Tucker (dtucker at zip.com.au)
GPG key 11EAA6FA / A86E 3E07 5B19 5880 E860  37F4 9357 ECEF 11EA A6FA (new)
    Good judgement comes with experience. Unfortunately, the experience
usually comes from bad judgement.
Reply | Threaded
Open this post in threaded view
|

Re: sshd(8) logging of client disconnect from ClientAliveInterval

Lars Noodén
On 10/17/17, Darren Tucker <[hidden email]> wrote:
[snip]
> probably better to use fmt_connection_id() instead of hand-rolling the
> format.

Ok.  I have added fmt_connection_id() to serverloop.c from packet.c

/Lars

Index: src/usr.bin/ssh/serverloop.c
===================================================================
RCS file: /cvs/src/usr.bin/ssh/serverloop.c,v
retrieving revision 1.198
diff -u -p -u -r1.198 serverloop.c
--- src/usr.bin/ssh/serverloop.c        12 Sep 2017 06:35:32 -0000      1.198
+++ src/usr.bin/ssh/serverloop.c        17 Oct 2017 09:57:34 -0000
@@ -162,10 +162,12 @@ static void
 client_alive_check(struct ssh *ssh)
 {
        int channel_id;
+       char remote_id[512];

        /* timeout, check to see how many we have had */
        if (packet_inc_alive_timeouts() > options.client_alive_count_max) {
-               logit("Timeout, client not responding.");
+               fmt_connection_id(ssh, remote_id, sizeof(remote_id));
+               logit("Timeout, client not responding from %s", remote_id);
                cleanup_exit(255);
        }

@@ -868,3 +870,12 @@ server_init_dispatch(void)
        /* rekeying */
        dispatch_set(SSH2_MSG_KEXINIT, &kex_input_kexinit);
 }
+
+fmt_connection_id(struct ssh *ssh, char *s, size_t l)
+{
+       snprintf(s, l, "%.200s%s%s port %d",
+           ssh->log_preamble ? ssh->log_preamble : "",
+           ssh->log_preamble ? " " : "",
+           ssh_remote_ipaddr(ssh), ssh_remote_port(ssh));
+}
+

Reply | Threaded
Open this post in threaded view
|

Re: sshd(8) logging of client disconnect from ClientAliveInterval

Lars Noodén
Here is a replacement patch.

/Lars

Index: serverloop.c
===================================================================
RCS file: /cvs/src/usr.bin/ssh/serverloop.c,v
retrieving revision 1.198
diff -u -p -u -r1.198 serverloop.c
--- serverloop.c        12 Sep 2017 06:35:32 -0000      1.198
+++ serverloop.c        17 Oct 2017 18:10:13 -0000
@@ -159,13 +159,24 @@ sigterm_handler(int sig)
 }

 static void
+fmt_connection_id(struct ssh *ssh, char *s, size_t l)
+{
+       snprintf(s, l, "%.200s%s%s port %d",
+           ssh->log_preamble ? ssh->log_preamble : "",
+           ssh->log_preamble ? " " : "",
+           ssh_remote_ipaddr(ssh), ssh_remote_port(ssh));
+}
+
+static void
 client_alive_check(struct ssh *ssh)
 {
        int channel_id;
+       char remote_id[512];

        /* timeout, check to see how many we have had */
        if (packet_inc_alive_timeouts() > options.client_alive_count_max) {
-               logit("Timeout, client not responding.");
+               fmt_connection_id(ssh, remote_id, sizeof(remote_id));
+               logit("Timeout, client not responding from %s", remote_id);
                cleanup_exit(255);
        }

@@ -868,3 +879,4 @@ server_init_dispatch(void)
        /* rekeying */
        dispatch_set(SSH2_MSG_KEXINIT, &kex_input_kexinit);
 }
+

Reply | Threaded
Open this post in threaded view
|

Re: sshd(8) logging of client disconnect from ClientAliveInterval

Darren Tucker
On Tue, Oct 17, 2017 at 09:10:38PM +0300, Lars Noodén wrote:
> Here is a replacement patch.

I meant reusing the existing function rather than cloning it.  It's
currently static so it needs to be exported but IMO that's better than
duplicating the code.

Index: packet.c
===================================================================
RCS file: /cvs/src/usr.bin/ssh/packet.c,v
retrieving revision 1.265
diff -u -p -r1.265 packet.c
--- packet.c 13 Oct 2017 21:13:54 -0000 1.265
+++ packet.c 17 Oct 2017 22:49:08 -0000
@@ -1773,8 +1773,8 @@ ssh_packet_send_debug(struct ssh *ssh, c
  fatal("%s: %s", __func__, ssh_err(r));
 }
 
-static void
-fmt_connection_id(struct ssh *ssh, char *s, size_t l)
+void
+sshpkt_fmt_connection_id(struct ssh *ssh, char *s, size_t l)
 {
  snprintf(s, l, "%.200s%s%s port %d",
     ssh->log_preamble ? ssh->log_preamble : "",
@@ -1790,7 +1790,7 @@ sshpkt_fatal(struct ssh *ssh, const char
 {
  char remote_id[512];
 
- fmt_connection_id(ssh, remote_id, sizeof(remote_id));
+ sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
 
  switch (r) {
  case SSH_ERR_CONN_CLOSED:
@@ -1852,7 +1852,7 @@ ssh_packet_disconnect(struct ssh *ssh, c
  * Format the message.  Note that the caller must make sure the
  * message is of limited size.
  */
- fmt_connection_id(ssh, remote_id, sizeof(remote_id));
+ sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
  va_start(args, fmt);
  vsnprintf(buf, sizeof(buf), fmt, args);
  va_end(args);
Index: packet.h
===================================================================
RCS file: /cvs/src/usr.bin/ssh/packet.h,v
retrieving revision 1.82
diff -u -p -r1.82 packet.h
--- packet.h 12 Sep 2017 06:32:07 -0000 1.82
+++ packet.h 17 Oct 2017 22:49:08 -0000
@@ -186,6 +186,7 @@ int sshpkt_get_cstring(struct ssh *ssh,
 int sshpkt_get_ec(struct ssh *ssh, EC_POINT *v, const EC_GROUP *g);
 int sshpkt_get_bignum2(struct ssh *ssh, BIGNUM *v);
 int sshpkt_get_end(struct ssh *ssh);
+void sshpkt_fmt_connection_id(struct ssh *ssh, char *s, size_t l);
 const u_char *sshpkt_ptr(struct ssh *, size_t *lenp);
 
 /* OLD API */
Index: serverloop.c
===================================================================
RCS file: /cvs/src/usr.bin/ssh/serverloop.c,v
retrieving revision 1.198
diff -u -p -r1.198 serverloop.c
--- serverloop.c 12 Sep 2017 06:35:32 -0000 1.198
+++ serverloop.c 17 Oct 2017 22:49:08 -0000
@@ -162,10 +162,12 @@ static void
 client_alive_check(struct ssh *ssh)
 {
  int channel_id;
+ char remote_id[512];
 
  /* timeout, check to see how many we have had */
  if (packet_inc_alive_timeouts() > options.client_alive_count_max) {
- logit("Timeout, client not responding.");
+ sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
+ logit("Timeout, client not responding from %s", remote_id);
  cleanup_exit(255);
  }
 

--
Darren Tucker (dtucker at zip.com.au)
GPG key 11EAA6FA / A86E 3E07 5B19 5880 E860  37F4 9357 ECEF 11EA A6FA (new)
    Good judgement comes with experience. Unfortunately, the experience
usually comes from bad judgement.

Reply | Threaded
Open this post in threaded view
|

Re: sshd(8) logging of client disconnect from ClientAliveInterval

Damien Miller
ok by me

On Wed, 18 Oct 2017, Darren Tucker wrote:

> On Tue, Oct 17, 2017 at 09:10:38PM +0300, Lars Noodén wrote:
> > Here is a replacement patch.
>
> I meant reusing the existing function rather than cloning it.  It's
> currently static so it needs to be exported but IMO that's better than
> duplicating the code.
>
> Index: packet.c
> ===================================================================
> RCS file: /cvs/src/usr.bin/ssh/packet.c,v
> retrieving revision 1.265
> diff -u -p -r1.265 packet.c
> --- packet.c 13 Oct 2017 21:13:54 -0000 1.265
> +++ packet.c 17 Oct 2017 22:49:08 -0000
> @@ -1773,8 +1773,8 @@ ssh_packet_send_debug(struct ssh *ssh, c
>   fatal("%s: %s", __func__, ssh_err(r));
>  }
>  
> -static void
> -fmt_connection_id(struct ssh *ssh, char *s, size_t l)
> +void
> +sshpkt_fmt_connection_id(struct ssh *ssh, char *s, size_t l)
>  {
>   snprintf(s, l, "%.200s%s%s port %d",
>      ssh->log_preamble ? ssh->log_preamble : "",
> @@ -1790,7 +1790,7 @@ sshpkt_fatal(struct ssh *ssh, const char
>  {
>   char remote_id[512];
>  
> - fmt_connection_id(ssh, remote_id, sizeof(remote_id));
> + sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
>  
>   switch (r) {
>   case SSH_ERR_CONN_CLOSED:
> @@ -1852,7 +1852,7 @@ ssh_packet_disconnect(struct ssh *ssh, c
>   * Format the message.  Note that the caller must make sure the
>   * message is of limited size.
>   */
> - fmt_connection_id(ssh, remote_id, sizeof(remote_id));
> + sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
>   va_start(args, fmt);
>   vsnprintf(buf, sizeof(buf), fmt, args);
>   va_end(args);
> Index: packet.h
> ===================================================================
> RCS file: /cvs/src/usr.bin/ssh/packet.h,v
> retrieving revision 1.82
> diff -u -p -r1.82 packet.h
> --- packet.h 12 Sep 2017 06:32:07 -0000 1.82
> +++ packet.h 17 Oct 2017 22:49:08 -0000
> @@ -186,6 +186,7 @@ int sshpkt_get_cstring(struct ssh *ssh,
>  int sshpkt_get_ec(struct ssh *ssh, EC_POINT *v, const EC_GROUP *g);
>  int sshpkt_get_bignum2(struct ssh *ssh, BIGNUM *v);
>  int sshpkt_get_end(struct ssh *ssh);
> +void sshpkt_fmt_connection_id(struct ssh *ssh, char *s, size_t l);
>  const u_char *sshpkt_ptr(struct ssh *, size_t *lenp);
>  
>  /* OLD API */
> Index: serverloop.c
> ===================================================================
> RCS file: /cvs/src/usr.bin/ssh/serverloop.c,v
> retrieving revision 1.198
> diff -u -p -r1.198 serverloop.c
> --- serverloop.c 12 Sep 2017 06:35:32 -0000 1.198
> +++ serverloop.c 17 Oct 2017 22:49:08 -0000
> @@ -162,10 +162,12 @@ static void
>  client_alive_check(struct ssh *ssh)
>  {
>   int channel_id;
> + char remote_id[512];
>  
>   /* timeout, check to see how many we have had */
>   if (packet_inc_alive_timeouts() > options.client_alive_count_max) {
> - logit("Timeout, client not responding.");
> + sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
> + logit("Timeout, client not responding from %s", remote_id);
>   cleanup_exit(255);
>   }
>  
>
> --
> Darren Tucker (dtucker at zip.com.au)
> GPG key 11EAA6FA / A86E 3E07 5B19 5880 E860  37F4 9357 ECEF 11EA A6FA (new)
>     Good judgement comes with experience. Unfortunately, the experience
> usually comes from bad judgement.
>
>
Reply | Threaded
Open this post in threaded view
|

Re: sshd(8) logging of client disconnect from ClientAliveInterval

Lars Noodén
In reply to this post by Darren Tucker
On Wed, 18 Oct 2017, Darren Tucker wrote:

> I meant reusing the existing function rather than cloning it.  It's
> currently static so it needs to be exported but IMO that's better than
> duplicating the code.
>
> Index: packet.c
> ===================================================================
> RCS file: /cvs/src/usr.bin/ssh/packet.c,v
> retrieving revision 1.265
> diff -u -p -r1.265 packet.c
> --- packet.c 13 Oct 2017 21:13:54 -0000 1.265
> +++ packet.c 17 Oct 2017 22:49:08 -0000
> @@ -1773,8 +1773,8 @@ ssh_packet_send_debug(struct ssh *ssh, c
>   fatal("%s: %s", __func__, ssh_err(r));
>  }
>  
> -static void
> -fmt_connection_id(struct ssh *ssh, char *s, size_t l)
> +void
> +sshpkt_fmt_connection_id(struct ssh *ssh, char *s, size_t l)
>  {
>   snprintf(s, l, "%.200s%s%s port %d",
>      ssh->log_preamble ? ssh->log_preamble : "",
> @@ -1790,7 +1790,7 @@ sshpkt_fatal(struct ssh *ssh, const char
>  {
>   char remote_id[512];
>  
> - fmt_connection_id(ssh, remote_id, sizeof(remote_id));
> + sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
>  
>   switch (r) {
>   case SSH_ERR_CONN_CLOSED:
> @@ -1852,7 +1852,7 @@ ssh_packet_disconnect(struct ssh *ssh, c
>   * Format the message.  Note that the caller must make sure the
>   * message is of limited size.
>   */
> - fmt_connection_id(ssh, remote_id, sizeof(remote_id));
> + sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
>   va_start(args, fmt);
>   vsnprintf(buf, sizeof(buf), fmt, args);
>   va_end(args);
> Index: packet.h
> ===================================================================
> RCS file: /cvs/src/usr.bin/ssh/packet.h,v
> retrieving revision 1.82
> diff -u -p -r1.82 packet.h
> --- packet.h 12 Sep 2017 06:32:07 -0000 1.82
> +++ packet.h 17 Oct 2017 22:49:08 -0000
> @@ -186,6 +186,7 @@ int sshpkt_get_cstring(struct ssh *ssh,
>  int sshpkt_get_ec(struct ssh *ssh, EC_POINT *v, const EC_GROUP *g);
>  int sshpkt_get_bignum2(struct ssh *ssh, BIGNUM *v);
>  int sshpkt_get_end(struct ssh *ssh);
> +void sshpkt_fmt_connection_id(struct ssh *ssh, char *s, size_t l);
>  const u_char *sshpkt_ptr(struct ssh *, size_t *lenp);
>  
>  /* OLD API */
> Index: serverloop.c
> ===================================================================
> RCS file: /cvs/src/usr.bin/ssh/serverloop.c,v
> retrieving revision 1.198
> diff -u -p -r1.198 serverloop.c
> --- serverloop.c 12 Sep 2017 06:35:32 -0000 1.198
> +++ serverloop.c 17 Oct 2017 22:49:08 -0000
> @@ -162,10 +162,12 @@ static void
>  client_alive_check(struct ssh *ssh)
>  {
>   int channel_id;
> + char remote_id[512];
>  
>   /* timeout, check to see how many we have had */
>   if (packet_inc_alive_timeouts() > options.client_alive_count_max) {
> - logit("Timeout, client not responding.");
> + sshpkt_fmt_connection_id(ssh, remote_id, sizeof(remote_id));
> + logit("Timeout, client not responding from %s", remote_id);
>   cleanup_exit(255);
>   }
>  
>

Yes, thanks.  That provides the log information I am looking for when a
client times out.  

/Lars