openssh unix dev - May 2024 - OpenSSH server doesn't log client disconnect without SSH_MSG_DISCONNECT

On Wed, May 22, 2024 at 6:29?AM Damien Miller <djm at mindrot.org>
wrote:
> On Tue, 21 May 2024, Opty wrote:
> > Hello,
> >
> > can anyone confirm that OpenSSH server doesn't log client
disconnect
> > without SSH_MSG_DISCONNECT?
>
> OpenSSH logs the disconnection regardless of whether the client sends
> SSH_MSG_DISCONNECT or just drops the connection.
>
> A little more information may be logged from the disconnect packet
> if it was sent, but there should always be a "Connection closed by
..."
> message regardless.
Unpatched:
2024-05-26T13:40:18.419241+02:00 qeporkak sshd 16107 - - Accepted
keyboard-interactive/pam for opty from 127.0.0.1 port 48133 ssh2
2024-05-26T13:40:18.428291+02:00 qeporkak elogind-daemon 1114 - - New
session 2 of user opty.
2024-05-26T13:40:19.309320+02:00 qeporkak elogind-daemon 1114 - -
Removed session 2.

Q&D patch:
diff -Naur a/putty-0.81/ssh/connection2.c b/putty-0.81/ssh/connection2.c
--- a/putty-0.81/ssh/connection2.c      2024-04-06 11:43:47.000000000 +0200
+++ b/putty-0.81/ssh/connection2.c      2024-05-26 14:00:38.382879095 +0200
@@ -1269,6 +1269,10 @@
          * and indeed OpenSSH feels this is more polite than sending a
          * DISCONNECT. So now we don't.
          */
+
+        /* We do again. */
+        ssh2_bpp_queue_disconnect(s->ppl.bpp, "disconnected by
user",
SSH2_DISCONNECT_BY_APPLICATION);
+
         ssh_user_close(s->ppl.ssh, "All channels closed");
         return;
     }

Patched:
2024-05-26T14:07:33.091682+02:00 qeporkak sshd 19168 - - Accepted
keyboard-interactive/pam for opty from 127.0.0.1 port 45639 ssh2
2024-05-26T14:07:33.107564+02:00 qeporkak elogind-daemon 1114 - - New
session 3 of user opty.
2024-05-26T14:07:34.335668+02:00 qeporkak sshd 19179 - - Received
disconnect from 127.0.0.1 port 45639:11: disconnected by user
2024-05-26T14:07:34.335790+02:00 qeporkak sshd 19179 - - Disconnected
from user opty 127.0.0.1 port 45639
2024-05-26T14:07:34.340569+02:00 qeporkak elogind-daemon 1114 - -
Removed session 3.

QED?

Regards,
Opty

On Sun, 26 May 2024, Opty wrote:
> On Wed, May 22, 2024 at 6:29?AM Damien Miller <djm at mindrot.org>
wrote:
> > On Tue, 21 May 2024, Opty wrote:
> > > Hello,
> > >
> > > can anyone confirm that OpenSSH server doesn't log client
disconnect
> > > without SSH_MSG_DISCONNECT?
> >
> > OpenSSH logs the disconnection regardless of whether the client sends
> > SSH_MSG_DISCONNECT or just drops the connection.
> >
> > A little more information may be logged from the disconnect packet
> > if it was sent, but there should always be a "Connection closed
by ..."
> > message regardless.
> 
> Unpatched:
> 2024-05-26T13:40:18.419241+02:00 qeporkak sshd 16107 - - Accepted
> keyboard-interactive/pam for opty from 127.0.0.1 port 48133 ssh2
> 2024-05-26T13:40:18.428291+02:00 qeporkak elogind-daemon 1114 - - New
> session 2 of user opty.
> 2024-05-26T13:40:19.309320+02:00 qeporkak elogind-daemon 1114 - -
> Removed session 2.
> 
> Q&D patch:
> diff -Naur a/putty-0.81/ssh/connection2.c b/putty-0.81/ssh/connection2.c
> --- a/putty-0.81/ssh/connection2.c      2024-04-06 11:43:47.000000000 +0200
> +++ b/putty-0.81/ssh/connection2.c      2024-05-26 14:00:38.382879095 +0200
> @@ -1269,6 +1269,10 @@
>           * and indeed OpenSSH feels this is more polite than sending a
>           * DISCONNECT. So now we don't.
>           */
> +
> +        /* We do again. */
> +        ssh2_bpp_queue_disconnect(s->ppl.bpp, "disconnected by
user",
> SSH2_DISCONNECT_BY_APPLICATION);
> +
>          ssh_user_close(s->ppl.ssh, "All channels closed");
>          return;
>      }
Yeah, you're adding a new thing that will be logged. IMO you should
try to figure out why the "Connection closed" message that is present
in the debug log you sent is not making to to your syslog.