Blacklistd and sshd not acting immediately according to logs

Buck · Oct 20, 2021

A curious thing that I'd like to understand. Blacklistd enabled in sshd config. Connecting from another external IP to ssh and issuing two wrong logins/passwords results in immediate lockout, as expected and defined in the config file. A new entry gets added to blacklistd table in pf as evidenced by pfctl -a blacklistd/22 -t port22 -T show. However every night I get snippets from auth.log that look like this:

Code:

Oct 18 19:10:56 mybox sshd[4141]: reverse mapping checking getaddrinfo for client.fttb.2day.kz [37.99.46.143] failed.
Oct 18 19:10:57 mybox sshd[4141]: Invalid user web from 37.99.46.143 port 11670
Oct 18 19:10:57 mybox sshd[4141]: Connection closed by invalid user web 37.99.46.143 port 11670 [preauth]
Oct 18 19:11:02 mybox sshd[4150]: reverse mapping checking getaddrinfo for client.fttb.2day.kz [37.99.46.143] failed.
Oct 18 19:11:02 mybox sshd[4150]: Invalid user web from 37.99.46.143 port 1704
Oct 18 19:11:02 mybox sshd[4150]: Connection closed by invalid user web 37.99.46.143 port 1704 [preauth]
Oct 18 19:11:08 mybox sshd[4154]: reverse mapping checking getaddrinfo for client.fttb.2day.kz [37.99.46.143] failed.
Oct 18 19:11:08 mybox sshd[4154]: Invalid user web from 37.99.46.143 port 13790
Oct 18 19:11:08 mybox sshd[4154]: Connection closed by invalid user web 37.99.46.143 port 13790 [preauth]
Oct 18 19:11:14 mybox sshd[4156]: reverse mapping checking getaddrinfo for client.fttb.2day.kz [37.99.46.143] failed.
Oct 18 19:11:15 mybox sshd[4156]: Invalid user web from 37.99.46.143 port 53966
Oct 18 19:11:15 mybox sshd[4156]: Connection closed by invalid user web 37.99.46.143 port 53966 [preauth]
Oct 18 19:11:21 mybox sshd[4158]: reverse mapping checking getaddrinfo for client.fttb.2day.kz [37.99.46.143] failed.
Oct 18 19:11:21 mybox sshd[4158]: Invalid user web from 37.99.46.143 port 28126
Oct 18 19:11:21 mybox sshd[4158]: Connection closed by invalid user web 37.99.46.143 port 28126 [preauth]
Oct 18 19:11:27 mybox sshd[4161]: reverse mapping checking getaddrinfo for client.fttb.2day.kz [37.99.46.143] failed.
Oct 18 19:11:27 mybox sshd[4161]: Invalid user web from 37.99.46.143 port 20549
Oct 18 19:11:27 mybox sshd[4161]: Connection closed by invalid user web 37.99.46.143 port 20549 [preauth]

37.99.46.143 never gets in the blocklist, those attempts just continue forever.

Looking further in auth.log reveals slight differences for IPs that did get the block:

Code:

Oct 20 09:58:45 mybox sshd[10097]: Address 209.141.56.75 maps to eubackup.wemineltc.com, but this does not map back to the address.
Oct 20 09:58:45 mybox sshd[10097]: Did not receive identification string from 209.141.56.75 port 56648
Oct 20 09:59:46 mybox sshd[10098]: Address 209.141.56.75 maps to eubackup.wemineltc.com, but this does not map back to the address.
Oct 20 09:59:59 mybox sshd[10098]: Received disconnect from 209.141.56.75 port 52446:11: Normal Shutdown, Thank you for playing [preauth]
Oct 20 09:59:59 mybox sshd[10098]: Disconnected from authenticating user root 209.141.56.75 port 52446 [preauth]
Oct 20 10:00:56 mybox sshd[10117]: Address 209.141.56.75 maps to eubackup.wemineltc.com, but this does not map back to the address.
Oct 20 10:01:03 mybox sshd[10117]: Received disconnect from 209.141.56.75 port 60352:11: Normal Shutdown, Thank you for playing [preauth]
Oct 20 10:01:03 mybox sshd[10117]: Disconnected from authenticating user root 209.141.56.75 port 60352 [preauth]
Oct 20 10:02:04 mybox sshd[10125]: Address 209.141.56.75 maps to eubackup.wemineltc.com, but this does not map back to the address.
Oct 20 10:02:15 mybox sshd[10125]: Invalid user ossuser from 209.141.56.75 port 40110

Apart from the obvious question of what's going on there exactly, i.e. why some IPs got blocked yet others don't, I'm curious why 209.141.56.75 specifically didn't get blocked after the second Disconnected from authenticating user root but got blocked after Invalid user ossuser - the same line that didn't trigger the block with 37.99.46.143.

tanis · Jan 12, 2022

I stumbled on the same issue setting up blacklistd, it seems the reason for that behavior can be found here:

Code:

    if (pw == NULL) {
        BLACKLIST_NOTIFY(ssh, BLACKLIST_BAD_USER, user);
        logit("Invalid user %.100s from %.100s port %d",
            user, ssh_remote_ipaddr(ssh), ssh_remote_port(ssh));

Src: https://github.com/freebsd/freebsd-...8ffb5defb5624/crypto/openssh/auth.c#L602-L605

Code:

    /* internal values are not the same as user application values */
    switch (action) {
    case BLACKLIST_AUTH_FAIL:
        internal_action = BL_ADD;
        break;
    case BLACKLIST_AUTH_OK:
        internal_action = BL_DELETE;
        break;
    case BLACKLIST_ABUSIVE_BEHAVIOR:
        internal_action = BL_ABUSE;
        break;
    case BLACKLIST_BAD_USER:
        internal_action = BL_BADUSER;
        break;
    default:
        internal_action = BL_INVALID;
        break;
    }

Src: https://github.com/freebsd/freebsd-...f2e/contrib/blacklist/lib/blacklist.c#L66-L83

Code:

    switch (bi->bi_type) {
    case BL_ABUSE:
        /*
         * If the application has signaled abusive behavior,
         * set the number of fails to be one less than the
         * configured limit.  Fallthrough to the normal BL_ADD
         * processing, which will increment the failure count
         * to the threshhold, and block the abusive address.
         */
        if (c.c_nfail != -1)
            dbi.count = c.c_nfail - 1;
        /*FALLTHROUGH*/
    case BL_ADD:
        dbi.count++;
        dbi.last = ts.tv_sec;
        if (dbi.id[0]) {
            /*
             * We should not be getting this since the rule
             * should have blocked the address. A possible
             * explanation is that someone removed that rule,
             * and another would be that we got another attempt
             * before we added the rule. In anycase, we remove
             * and re-add the rule because we don't want to add
             * it twice, because then we'd lose track of it.
             */
            (*lfun)(LOG_DEBUG, "rule exists %s", dbi.id);
            (void)run_change("rem", &c, dbi.id, 0);
            dbi.id[0] = '\0';
        }
        if (c.c_nfail != -1 && dbi.count >= c.c_nfail) {
            int res = run_change("add", &c, dbi.id, sizeof(dbi.id));
            if (res == -1)
                goto out;
            sockaddr_snprintf(rbuf, sizeof(rbuf), "%a",
                (void *)&rss);
            (*lfun)(LOG_INFO,
                "blocked %s/%d:%d for %d seconds",
                rbuf, c.c_lmask, c.c_port, c.c_duration);
              
        }
        break;
    case BL_DELETE:
        if (dbi.last == 0)
            goto out;
        dbi.count = 0;
        dbi.last = 0;
        break;
    case BL_BADUSER:
        /* ignore for now */
        break;
    default:
        (*lfun)(LOG_ERR, "unknown message %d", bi->bi_type);
    }

Src: https://github.com/freebsd/freebsd-.../contrib/blacklist/bin/blacklistd.c#L216-L268

Edit:
Unfortunately I don't understand the intenion to handle BL_BADUSER ( BLACKLIST_BAD_USER) different from BL_ABUSE (BLACKLIST_ABUSIVE_BEHAVIOR). From my point of view there is no difference and I would handle them the same, I would even go so far and drop BL_BADUSER in favour for BL_ABUSE? It seems I'm a bit rusty in that department

, spend some time with the code and getting closer.

~~Can anybody with some more insight shade some more light on this ? What the idea here is and why BL_ABUSE and BL_BADUSER have been introduced in the first place ?~~ Getting here closer as well.

tanis · Jan 14, 2022

So I guess the question is want do we want here? Should an invalid username be treated the same as a wrong password?

IMHO: Yes.
What is the down side?

I can't really see anything, depending on the use case, I need to increase the max failures.

Anyone else ?

As the change is rather simple:

Code:

--- blacklistd-2022-01-13.c     

+++ blacklistd.c

@@ -225,6 +225,8 @@

                if (c.c_nfail != -1)

                        dbi.count = c.c_nfail - 1;

                /*FALLTHROUGH*/

+       case BL_BADUSER:

+               /*FALLTHROUGH*/

        case BL_ADD:

                dbi.count++;

                dbi.last = ts.tv_sec;

@@ -259,9 +261,6 @@

                        goto out;

                dbi.count = 0;

                dbi.last = 0;

-               break;

-       case BL_BADUSER:

-               /* ignore for now */

                break;

        default:

                (*lfun)(LOG_ERR, "unknown message %d", bi->bi_type);

I did that last night, and now I have now a vm exposed to the Wild running blacklistd patched in that way, to see how it works out in the long game.

Next I will patch one of my production systems I guess.

I also checked upstream, NetBSD hasn't decided on that as well, so I don't know.

Blacklistd and sshd not acting immediately according to logs

Buck

tanis

tanis