On Fri, Aug 18, 2023 at 06:43:50PM +0100, Stuart Henderson wrote:
> On 2023/08/18 17:39, Tobias Heider wrote:
> > Hi,
> >
> > I was looking at my authlog today and as expected on a server exposed on the
> > public internet it is filled with random scanners and brute force attacks.
> > One thing I noticed is that there is a lot of information we log multiple
> > times for a each failed connection.
> >
> > Some examples below:
> >
> > sshd[6216]: error: kex_exchange_identification: banner line contains
> > invalid characters
> > sshd[6216]: banner exchange: Connection from xx.97.73.149 port 64744:
> > invalid format
> > sshd[68416]: error: kex_exchange_identification: banner line contains
> > invalid characters
> > sshd[68416]: banner exchange: Connection from xx.97.73.149 port 63955:
> > invalid format
> >
> > There are a few more parsing errors like this that result in a print of the
> > exact
> > issue error followed by 'goto invalid' which causes the more general
> > "invalid format"
> > message. I think "invalid format" is enough information in most cases.
> >
> > sshd[50752]: error: kex_exchange_identification: Connection closed by
> > remote host
> > sshd[50752]: Connection closed by xx.94.81.243 port 61000
> >
> > Same as above, the kex_exchange_identification doesn't really add anything.
> >
> > sshd[51579]: Invalid user tom from xx.134.191.142 port 35480
> > sshd[51579]: Received disconnect from xx.134.191.142 port 35480:11: Bye Bye
> > [preauth]
> > sshd[51579]: Disconnected from invalid user tom xx.134.191.142 port 35480
> > [preauth]
> > sshd[94857]: Invalid user long from xx.97.173.1 port 51140
> > sshd[94857]: Received disconnect from xx.97.173.1 port 51140:11: Bye Bye
> > [preauth]
> > sshd[94857]: Disconnected from invalid user long xx.97.173.1 port 51140
> > [preauth]
> >
> > Here the "Disconnected" line contains all the info from "Invalid user" line.
> > Those invalid user messages make up the largest part of my log file,
> > so deduplicating them makes a huge difference.
> >
> > Below is a diff to make some of those log to debug if the same information
> > is also logged elsewhere.
> > Is there some general interest in diffs to clean this up a bit?
>
> There are some messages which don't show up in the "Disconnected from"
> line which may possibly give some clues about the source of connections,
> so might be of interest. If someone does want to log them, going all
> the way to debug is going to result in a *lot* more useless lines being
> logged.
>
> So if they are getting squelched I think they would better under verbose
> rather than debug.
Right, verbose is probably a better choice.
>
> examples...
>
> sshd[2722]: Connection from 20.168.51.56 port 54850 on 195.95.187.26 port 22
> rdomain "0"
> sshd[2722]: error: Received disconnect from 20.168.51.56 port 54850:3:
> com.jcraft.jsch.JSchException: Auth fail [preauth]
> sshd[2722]: Disconnected from authenticating user root 20.168.51.56 port
> 54850 [preauth]
>
> sshd[50247]: Connection from 218.92.0.22 port 36077 on 195.95.187.184 port 22
> rdomain "0"
> sshd[50247]: Received disconnect from 218.92.0.22 port 36077:11: [preauth]
> sshd[50247]: Disconnected from authenticating user root 218.92.0.22 port
> 36077 [preauth]
>
> sshd[12117]: Connection from 222.71.84.234 port 53262 on 195.95.187.26 port
> 22 rdomain "0"
> sshd[12117]: Invalid user A@0599343813A@0599343813A@0599343813 from
> 222.71.84.234 port 53262
> sshd[12117]: Received disconnect from 222.71.84.234 port 53262:11: Normal
> Shutdown, Thank you for playing [preauth]
> sshd[12117]: Disconnected from invalid user
> A@0599343813A@0599343813A@0599343813 222.71.84.234 port 53262 [preauth]
>
> sshd[83269]: Connection from 143.244.50.173 port 46078 on 195.95.187.28 port
> 22 rdomain "0"
> sshd[83269]: Invalid user admin from 143.244.50.173 port 46078
> sshd[83269]: Received disconnect from 143.244.50.173 port 46078:11: end
> [preauth]
> sshd[83269]: Disconnected from invalid user admin 143.244.50.173 port 46078
> [preauth]
>
> and I have all sorts in "kex_exchange_identification: client sent
> invalid protocol identifier"
That one should already be included with my diff. That's one of those goto
invalid cases.
Updated diff with s/debug/verbose/ below.
Index: auth.c
===================================================================
RCS file: /cvs/src/usr.bin/ssh/auth.c,v
retrieving revision 1.160
diff -u -p -r1.160 auth.c
--- auth.c 5 Mar 2023 05:34:09 -0000 1.160
+++ auth.c 18 Aug 2023 18:01:49 -0000
@@ -431,7 +431,7 @@ getpwnamallow(struct ssh *ssh, const cha
pw = getpwnam(user);
if (pw == NULL) {
- logit("Invalid user %.100s from %.100s port %d",
+ verbose("Invalid user %.100s from %.100s port %d",
user, ssh_remote_ipaddr(ssh), ssh_remote_port(ssh));
return (NULL);
}
Index: kex.c
===================================================================
RCS file: /cvs/src/usr.bin/ssh/kex.c,v
retrieving revision 1.179
diff -u -p -r1.179 kex.c
--- kex.c 18 Aug 2023 01:37:41 -0000 1.179
+++ kex.c 18 Aug 2023 18:01:50 -0000
@@ -1336,7 +1336,7 @@ kex_exchange_identification(struct ssh *
len = atomicio(read, ssh_packet_get_connection_in(ssh),
&c, 1);
if (len != 1 && errno == EPIPE) {
- error_f("Connection closed by remote host");
+ verbose_f("Connection closed by remote host");
r = SSH_ERR_CONN_CLOSED;
goto out;
} else if (len != 1) {
@@ -1352,7 +1352,7 @@ kex_exchange_identification(struct ssh *
if (c == '\n')
break;
if (c == '\0' || expect_nl) {
- error_f("banner line contains invalid "
+ verbose_f("banner line contains invalid "
"characters");
goto invalid;
}
@@ -1362,7 +1362,7 @@ kex_exchange_identification(struct ssh *
goto out;
}
if (sshbuf_len(peer_version) > SSH_MAX_BANNER_LEN) {
- error_f("banner line too long");
+ verbose_f("banner line too long");
goto invalid;
}
}
@@ -1378,7 +1378,7 @@ kex_exchange_identification(struct ssh *
}
/* Do not accept lines before the SSH ident from a client */
if (ssh->kex->server) {
- error_f("client sent invalid protocol identifier "
+ verbose_f("client sent invalid protocol identifier "
"\"%.256s\"", cp);
free(cp);
goto invalid;
