• Looking for help / advice against aggressive BotNet triggering sshd err

    From JT High@21:1/5 to All on Fri Sep 18 07:53:09 2020
    I'm looking for any help / advice against aggressive BotNet triggering sshd errors which fill auth.log rapidly.... What I am seeing could be a legitimate sshd bug -- or it could be a misconfiguration on my part that I've never encountered before...

    I have a small linux host which is now and has been kept up to date, and has to the best of my ability been hardened for SSH and had fail2ban installed on it. Generally this host deals with the typical SSH Internet brute force attempts fine, and
    fail2ban bans recurring source IP attempts as planned.

    This past week something "New and unexpected" happened... a botnet came after this host, and although I don't see any sign they ever successfully authenticated (which is also protected by google-authenticator-libpam), they nevertheless managed to do
    something that FILLed auth.log very rapidly, and effectively crashed the host until I realized it had a problem. None of what they were doing triggered jail from Fail2Ban which I get email notifications for...

    The auth.log on this host (a sample is shown below) grew to 11GB rapidly and shows more than 250 source IPs from all around the world converging on this host with two or three at a time making attempts -- not just the typical script kiddie / dictionary
    attacks either - whoever this is intentionally never stayed on the same IPs long enough the get banned and the recycling of source IPs was carefully done...

    In /var/log/auth.log I see this:

    Please note the topmost line, and the lines at the bottom, that look like this: Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:1: type is not 2

    There are millions of these lines with different integers, and an astonishing number of them were written quickly into auth.log, but none of this activity seemed to generate a ban out of fail2ban

    Can someone more skilled than me - please eyeball this log snippet and tell me if I should bother anyone with a bug report, or if I am the one with the 'config' problem?

    This host does not have any file system corruption and regenerating the primes doesn't seem to fix this issue, as this botnet can illicit the same effect over and over again... manually banning the offending source IPs just slows things down for a short
    while and they are right back at me from other IPs. Sadly - whoever has control of this botnet is not just running out of China, Russian, Iran, etc. they also have numerous source IPs in the USA -- New York, California, Washington State, etc. so
    blocking incoming connections outside of North America may not be a complete solution....

    ---------------------------------------------------

    Sep 15 17:34:45 rp6 sshd[21258]: WARNING: no suitable primes in /etc/ssh/moduli Sep 15 17:34:45 rp6 sshd[21258]: debug2: monitor_read: 0 used once, disabling now
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug2: bits set: 1053/2048 [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: Connection closed by <REDACTED IP> port 58879 [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: do_cleanup [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: monitor_read_log: child log fd closed Sep 15 17:34:45 rp6 sshd[21258]: debug1: do_cleanup
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: Killing privsep child 21259
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: audit_event: unhandled event 12
    Sep 15 17:35:03 rp6 sshd[660]: debug1: Forked child 21262.
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Set /proc/self/oom_score_adj to 0
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: inetd sockets after dupping: 3, 3
    Sep 15 17:35:03 rp6 sshd[21262]: Connection from <REDACTED IP> port 57168 on 192.168.86.25 port 22
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Client protocol version 2.0; client software version libssh-0.6.3
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: no match: libssh-0.6.3
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Raspbian-10+deb10u2
    Sep 15 17:35:03 rp6 sshd[21262]: debug2: fd 3 setting O_NONBLOCK
    Sep 15 17:35:03 rp6 sshd[21262]: debug2: Network child is on pid 21263
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: permanently_set_uid: 107/65534 [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: list_hostkey_types: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: SSH2_MSG_KEXINIT sent [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: Connection closed by 138.197.222.141 port 57168 [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: do_cleanup [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: monitor_read_log: child log fd closed Sep 15 17:35:03 rp6 sshd[21262]: debug1: do_cleanup
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Killing privsep child 21263
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: audit_event: unhandled event 12
    Sep 15 17:35:25 rp6 sshd[660]: debug1: Forked child 21265.
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Set /proc/self/oom_score_adj to 0
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: inetd sockets after dupping: 3, 3
    Sep 15 17:35:25 rp6 sshd[21265]: Connection from <REDACTED IP> port 58879 on 192.168.86.25 port 22
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Client protocol version 2.0; client software version libssh2_1.8.0
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: no match: libssh2_1.8.0
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Raspbian-10+deb10u2
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: fd 3 setting O_NONBLOCK
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: Network child is on pid 21266
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: permanently_set_uid: 107/65534 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: list_hostkey_types: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: SSH2_MSG_KEXINIT sent [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: SSH2_MSG_KEXINIT received [preauth] Sep 15 17:35:25 rp6 sshd[21265]: debug2: local server KEXINIT proposal [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: KEX algorithms: curve25519-sha256@libssh.org,diffie-hellman-group-exchange-sha256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: host key algorithms: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs ctos: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512,hmac-sha2-256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs stoc: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512,hmac-sha2-256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression ctos: none,zlib@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression stoc: none,zlib@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages ctos: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages stoc: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: first_kex_follows 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: reserved 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: peer client KEXINIT proposal [preauth] Sep 15 17:35:25 rp6 sshd[21265]: debug2: KEX algorithms: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: host key algorithms: ssh-rsa,ssh-dss [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers ctos: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers stoc: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs ctos: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs stoc: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression ctos: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression stoc: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages ctos: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages stoc: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: first_kex_follows 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: reserved 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: algorithm: diffie-hellman-group-exchange-sha256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: host key algorithm: ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: expecting SSH2_MSG_KEX_DH_GEX_REQUEST [preauth]
    Sep 15 17:35:26 rp6 sshd[21265]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received [preauth]
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:1: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:2: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:3: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:4: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:5: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:6: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:7: type is not 2

    (ad nauseum....)

    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)
  • From William Unruh@21:1/5 to JT High on Fri Sep 18 20:30:45 2020
    On 2020-09-18, JT High <jthigh@gmail.com> wrote:
    I'm looking for any help / advice against aggressive BotNet triggering sshd errors which fill auth.log rapidly.... What I am seeing could be a legitimate sshd bug -- or it could be a misconfiguration on my part that I've never encountered before...

    I have a small linux host which is now and has been kept up to date, and has to the best of my ability been hardened for SSH and had fail2ban installed on it. Generally this host deals with the typical SSH Internet brute force attempts fine, and
    fail2ban bans recurring source IP attempts as planned.

    Why do you have debug (-dd) enabled for sshd?

    fail2ban looks for bad usernames/failed passwords as far as I know, not
    debug messages.



    This past week something "New and unexpected" happened... a botnet came after this host, and although I don't see any sign they ever successfully authenticated (which is also protected by google-authenticator-libpam), they nevertheless managed to do
    something that FILLed auth.log very rapidly, and effectively crashed the host until I realized it had a problem. None of what they were doing triggered jail from Fail2Ban which I get email notifications for...

    The auth.log on this host (a sample is shown below) grew to 11GB rapidly and shows more than 250 source IPs from all around the world converging on this host with two or three at a time making attempts -- not just the typical script kiddie / dictionary
    attacks either - whoever this is intentionally never stayed on the same IPs long enough the get banned and the recycling of source IPs was carefully done...

    In /var/log/auth.log I see this:

    Please note the topmost line, and the lines at the bottom, that look like this:
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:1: type is not 2

    There are millions of these lines with different integers, and an astonishing number of them were written quickly into auth.log, but none of this activity seemed to generate a ban out of fail2ban

    Can someone more skilled than me - please eyeball this log snippet and tell me if I should bother anyone with a bug report, or if I am the one with the 'config' problem?

    This host does not have any file system corruption and regenerating the primes doesn't seem to fix this issue, as this botnet can illicit the same effect over and over again... manually banning the offending source IPs just slows things down for a
    short while and they are right back at me from other IPs. Sadly - whoever has control of this botnet is not just running out of China, Russian, Iran, etc. they also have numerous source IPs in the USA -- New York, California, Washington State, etc. so
    blocking incoming connections outside of North America may not be a complete solution....

    ---------------------------------------------------

    Sep 15 17:34:45 rp6 sshd[21258]: WARNING: no suitable primes in /etc/ssh/moduli
    Sep 15 17:34:45 rp6 sshd[21258]: debug2: monitor_read: 0 used once, disabling now
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug2: bits set: 1053/2048 [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: Connection closed by <REDACTED IP> port 58879 [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: do_cleanup [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: monitor_read_log: child log fd closed
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: do_cleanup
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: Killing privsep child 21259
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: audit_event: unhandled event 12
    Sep 15 17:35:03 rp6 sshd[660]: debug1: Forked child 21262.
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Set /proc/self/oom_score_adj to 0 Sep 15 17:35:03 rp6 sshd[21262]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: inetd sockets after dupping: 3, 3 Sep 15 17:35:03 rp6 sshd[21262]: Connection from <REDACTED IP> port 57168 on 192.168.86.25 port 22
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Client protocol version 2.0; client software version libssh-0.6.3
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: no match: libssh-0.6.3
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Raspbian-10+deb10u2
    Sep 15 17:35:03 rp6 sshd[21262]: debug2: fd 3 setting O_NONBLOCK
    Sep 15 17:35:03 rp6 sshd[21262]: debug2: Network child is on pid 21263
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: permanently_set_uid: 107/65534 [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: list_hostkey_types: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: SSH2_MSG_KEXINIT sent [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: Connection closed by 138.197.222.141 port 57168 [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: do_cleanup [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: monitor_read_log: child log fd closed
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: do_cleanup
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Killing privsep child 21263
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: audit_event: unhandled event 12
    Sep 15 17:35:25 rp6 sshd[660]: debug1: Forked child 21265.
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Set /proc/self/oom_score_adj to 0 Sep 15 17:35:25 rp6 sshd[21265]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: inetd sockets after dupping: 3, 3 Sep 15 17:35:25 rp6 sshd[21265]: Connection from <REDACTED IP> port 58879 on 192.168.86.25 port 22
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Client protocol version 2.0; client software version libssh2_1.8.0
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: no match: libssh2_1.8.0
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Raspbian-10+deb10u2
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: fd 3 setting O_NONBLOCK
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: Network child is on pid 21266
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: permanently_set_uid: 107/65534 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: list_hostkey_types: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: SSH2_MSG_KEXINIT sent [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: SSH2_MSG_KEXINIT received [preauth] Sep 15 17:35:25 rp6 sshd[21265]: debug2: local server KEXINIT proposal [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: KEX algorithms: curve25519-sha256@libssh.org,diffie-hellman-group-exchange-sha256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: host key algorithms: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs ctos: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512,hmac-sha2-256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs stoc: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-512,hmac-sha2-256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression ctos: none,zlib@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression stoc: none,zlib@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages ctos: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages stoc: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: first_kex_follows 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: reserved 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: peer client KEXINIT proposal [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: KEX algorithms: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: host key algorithms: ssh-rsa,ssh-dss [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers ctos: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers stoc: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs ctos: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs stoc: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ripemd160@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression ctos: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression stoc: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages ctos: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages stoc: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: first_kex_follows 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: reserved 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: algorithm: diffie-hellman-group-exchange-sha256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: host key algorithm: ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: expecting SSH2_MSG_KEX_DH_GEX_REQUEST [preauth]
    Sep 15 17:35:26 rp6 sshd[21265]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received [preauth]
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:1: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:2: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:3: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:4: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:5: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:6: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:7: type is not 2

    (ad nauseum....)


    Look in /etc/moduli The moduli should be type 2, which is what ssh
    requires. If they are not type 2 they will not be useful and that seems
    to be what is being complained about. The type is the second number in
    each line.

    (I have over 400 moduli all of type 2)

    So have a look at your file to see what is happening in there. It might
    be that something messed up you /etc/ssh/moduli file. Go into a backup
    from a while ago and see if there is reasonable one there.




    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)
  • From JT High@21:1/5 to William Unruh on Sat Sep 19 19:18:11 2020
    William - thank you so much for the direction!

    I'm not sure how debug was turned on for sshd, (maybe some prior troubleshooting that was left turned on) but you are right - it was on and that certainly caused auth.log to fill up much more quickly than normal.

    Fail2Ban as you suggested, out of the box, doesn't jail anything untoward going on in auth.log for sshd, in this case the BotNet with > 250 source IPs were able
    to generate 10GB of auth.log (albeit with DEBUG on sshd) in a short period without technically getting a failed password, as they never made it to the prompt to enter a 2nd factor code, much less a correct password.

    I see there are discussions / feature requests on github where people desire more regex filters to find some of these patterns and to jail them also, even if the source IP is not technically making it to, and failing with a bad password type entry in
    auth.log -> https://github.com/fail2ban/fail2ban/issues; If you are going to use multi-factor, and require that code before the password that definitely changes what Fail2Ban sees in Auth.log

    * Turned debug on sshd down to verbose, cleaned up the moduli file, and did a refresh of the sshd hardening via https://www.sshaudit.com/ and all seems well now.







    On Friday, September 18, 2020 at 4:30:47 PM UTC-4, William Unruh wrote:
    On 2020-09-18, JT High <jth...@gmail.com> wrote:
    I'm looking for any help / advice against aggressive BotNet triggering sshd errors which fill auth.log rapidly.... What I am seeing could be a legitimate sshd bug -- or it could be a misconfiguration on my part that I've never encountered before...

    I have a small linux host which is now and has been kept up to date, and has to the best of my ability been hardened for SSH and had fail2ban installed on it. Generally this host deals with the typical SSH Internet brute force attempts fine, and
    fail2ban bans recurring source IP attempts as planned.
    Why do you have debug (-dd) enabled for sshd?

    fail2ban looks for bad usernames/failed passwords as far as I know, not debug messages.

    This past week something "New and unexpected" happened... a botnet came after this host, and although I don't see any sign they ever successfully authenticated (which is also protected by google-authenticator-libpam), they nevertheless managed to do
    something that FILLed auth.log very rapidly, and effectively crashed the host until I realized it had a problem. None of what they were doing triggered jail from Fail2Ban which I get email notifications for...

    The auth.log on this host (a sample is shown below) grew to 11GB rapidly and shows more than 250 source IPs from all around the world converging on this host with two or three at a time making attempts -- not just the typical script kiddie /
    dictionary attacks either - whoever this is intentionally never stayed on the same IPs long enough the get banned and the recycling of source IPs was carefully done...

    In /var/log/auth.log I see this:

    Please note the topmost line, and the lines at the bottom, that look like this:
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:1: type is not 2

    There are millions of these lines with different integers, and an astonishing number of them were written quickly into auth.log, but none of this activity seemed to generate a ban out of fail2ban

    Can someone more skilled than me - please eyeball this log snippet and tell me if I should bother anyone with a bug report, or if I am the one with the 'config' problem?

    This host does not have any file system corruption and regenerating the primes doesn't seem to fix this issue, as this botnet can illicit the same effect over and over again... manually banning the offending source IPs just slows things down for a
    short while and they are right back at me from other IPs. Sadly - whoever has control of this botnet is not just running out of China, Russian, Iran, etc. they also have numerous source IPs in the USA -- New York, California, Washington State, etc. so
    blocking incoming connections outside of North America may not be a complete solution....

    ---------------------------------------------------

    Sep 15 17:34:45 rp6 sshd[21258]: WARNING: no suitable primes in /etc/ssh/moduli
    Sep 15 17:34:45 rp6 sshd[21258]: debug2: monitor_read: 0 used once, disabling now
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug2: bits set: 1053/2048 [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: Connection closed by <REDACTED IP> port 58879 [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: do_cleanup [preauth]
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: monitor_read_log: child log fd closed
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: do_cleanup
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: Killing privsep child 21259
    Sep 15 17:34:45 rp6 sshd[21258]: debug1: audit_event: unhandled event 12 Sep 15 17:35:03 rp6 sshd[660]: debug1: Forked child 21262.
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Set /proc/self/oom_score_adj to 0 Sep 15 17:35:03 rp6 sshd[21262]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: inetd sockets after dupping: 3, 3 Sep 15 17:35:03 rp6 sshd[21262]: Connection from <REDACTED IP> port 57168 on 192.168.86.25 port 22
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Client protocol version 2.0; client software version libssh-0.6.3
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: no match: libssh-0.6.3
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Raspbian-10+deb10u2
    Sep 15 17:35:03 rp6 sshd[21262]: debug2: fd 3 setting O_NONBLOCK
    Sep 15 17:35:03 rp6 sshd[21262]: debug2: Network child is on pid 21263
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: permanently_set_uid: 107/65534 [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: list_hostkey_types: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: SSH2_MSG_KEXINIT sent [preauth] Sep 15 17:35:03 rp6 sshd[21262]: Connection closed by 138.197.222.141 port 57168 [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: do_cleanup [preauth]
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: monitor_read_log: child log fd closed
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: do_cleanup
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: Killing privsep child 21263
    Sep 15 17:35:03 rp6 sshd[21262]: debug1: audit_event: unhandled event 12 Sep 15 17:35:25 rp6 sshd[660]: debug1: Forked child 21265.
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Set /proc/self/oom_score_adj to 0 Sep 15 17:35:25 rp6 sshd[21265]: debug1: rexec start in 7 out 7 newsock 7 pipe 9 sock 10
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: inetd sockets after dupping: 3, 3 Sep 15 17:35:25 rp6 sshd[21265]: Connection from <REDACTED IP> port 58879 on 192.168.86.25 port 22
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Client protocol version 2.0; client software version libssh2_1.8.0
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: no match: libssh2_1.8.0
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Raspbian-10+deb10u2
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: fd 3 setting O_NONBLOCK
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: Network child is on pid 21266
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: permanently_set_uid: 107/65534 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: list_hostkey_types: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: SSH2_MSG_KEXINIT sent [preauth] Sep 15 17:35:25 rp6 sshd[21265]: debug1: SSH2_MSG_KEXINIT received [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: local server KEXINIT proposal [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: KEX algorithms: curve255...@libssh.org,diffie-hellman-group-exchange-sha256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: host key algorithms: ssh-ed25519,ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers ctos: chacha20...@openssh.com,aes25...@openssh.com,aes12...@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers stoc: chacha20...@openssh.com,aes25...@openssh.com,aes12...@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs ctos: hmac-sha...@openssh.com,hmac-sha...@openssh.com,umac-1...@openssh.com,hmac-sha2-512,hmac-sha2-256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs stoc: hmac-sha...@openssh.com,hmac-sha...@openssh.com,umac-1...@openssh.com,hmac-sha2-512,hmac-sha2-256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression ctos: none,zl...@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression stoc: none,zl...@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages ctos: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages stoc: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: first_kex_follows 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: reserved 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: peer client KEXINIT proposal [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: KEX algorithms: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: host key algorithms: ssh-rsa,ssh-dss [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers ctos: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijnda...@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: ciphers stoc: aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijnda...@lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs ctos: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ri...@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: MACs stoc: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,hmac-ri...@openssh.com [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression ctos: none [preauth] Sep 15 17:35:25 rp6 sshd[21265]: debug2: compression stoc: none [preauth] Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages ctos: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: languages stoc: [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: first_kex_follows 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug2: reserved 0 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: algorithm: diffie-hellman-group-exchange-sha256 [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: host key algorithm: ssh-rsa [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
    Sep 15 17:35:25 rp6 sshd[21265]: debug1: expecting SSH2_MSG_KEX_DH_GEX_REQUEST [preauth]
    Sep 15 17:35:26 rp6 sshd[21265]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received [preauth]
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:1: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:2: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:3: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:4: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:5: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:6: type is not 2
    Sep 15 17:35:26 rp6 sshd[21265]: error: moduli:7: type is not 2

    (ad nauseum....)

    Look in /etc/moduli The moduli should be type 2, which is what ssh
    requires. If they are not type 2 they will not be useful and that seems
    to be what is being complained about. The type is the second number in
    each line.

    (I have over 400 moduli all of type 2)

    So have a look at your file to see what is happening in there. It might
    be that something messed up you /etc/ssh/moduli file. Go into a backup
    from a while ago and see if there is reasonable one there.




    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)