Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 54c7a5f1 authored by Jeff Vander Stoep's avatar Jeff Vander Stoep
Browse files

LogAudit: remove dynamic rate limiter 

Select a low rate-limit to cut down on logspam and resulting
performance regressions.

Functionally reverts 247d682f
(logd: sepolicy dynamic rate limiting) and sets a static low
rate-limit. Before 247d682f, the limit was statically set to 20.
247d682f continued to support 20, but if sustained dropped the limit
to 5. This revert leaves us at 5 so as not to impact performance.

Test: /data/nativetest/logd-unit-tests/logd-unit-tests \
    --gtest_filter=logd.sepolicy_rate_limiter
    [  PASSED  ] 1 test.
Bug: 71538411
Change-Id: I6c92f4ba825cc24beb8f1f1b79258fa8097c837b
parent 93d344d9

logd/LogAudit.cpp

+2 −46
Original line number Diff line number Diff line
@@ -45,7 +45,7 @@ 
        '0' + LOG_MAKEPRI(LOG_AUTH, LOG_PRI(PRI)) % 10, '>'



LogAudit::LogAudit(LogBuffer* buf, LogReader* reader, int fdDmesg)

    : SocketListener(mSock = getLogSocket(), false),

    : SocketListener(getLogSocket(), false),

      logbuf(buf),

      reader(reader),

      fdDmesg(fdDmesg),
@@ -53,8 +53,7 @@ LogAudit::LogAudit(LogBuffer* buf, LogReader* reader, int fdDmesg) 
                                              BOOL_DEFAULT_TRUE)),

      events(__android_logger_property_get_bool("ro.logd.auditd.events",

                                                BOOL_DEFAULT_TRUE)),

      initialized(false),

      tooFast(false) {

      initialized(false) {

    static const char auditd_message[] = { KMSG_PRIORITY(LOG_INFO),

                                           'l',

                                           'o',
@@ -78,54 +77,12 @@ LogAudit::LogAudit(LogBuffer* buf, LogReader* reader, int fdDmesg) 
    write(fdDmesg, auditd_message, sizeof(auditd_message));

}



void LogAudit::checkRateLimit() {

    // trim list for AUDIT_RATE_LIMIT_BURST_DURATION of history

    log_time oldest(AUDIT_RATE_LIMIT_BURST_DURATION, 0);

    bucket.emplace(android_log_clockid());

    oldest = bucket.back() - oldest;

    while (bucket.front() < oldest) bucket.pop();



    static const size_t upperThreshold =

        ((AUDIT_RATE_LIMIT_BURST_DURATION *

          (AUDIT_RATE_LIMIT_DEFAULT + AUDIT_RATE_LIMIT_MAX)) +

         1) /

        2;

    if (bucket.size() >= upperThreshold) {

        // Hit peak, slow down source

        if (!tooFast) {

            tooFast = true;

            audit_rate_limit(mSock, AUDIT_RATE_LIMIT_MAX);

        }



        // We do not need to hold on to the full set of timing data history,

        // let's ensure it does not grow without bounds.  This also ensures

        // that std::dequeue underneath behaves almost like a ring buffer.

        do {

            bucket.pop();

        } while (bucket.size() >= upperThreshold);

        return;

    }



    if (!tooFast) return;



    static const size_t lowerThreshold =

        AUDIT_RATE_LIMIT_BURST_DURATION * AUDIT_RATE_LIMIT_MAX;



    if (bucket.size() >= lowerThreshold) return;



    tooFast = false;

    // Went below max sustained rate, allow source to speed up

    audit_rate_limit(mSock, AUDIT_RATE_LIMIT_DEFAULT);

}



bool LogAudit::onDataAvailable(SocketClient* cli) {

    if (!initialized) {

        prctl(PR_SET_NAME, "logd.auditd");

        initialized = true;

    }



    checkRateLimit();



    struct audit_message rep;



    rep.nlh.nlmsg_type = 0;
@@ -486,6 +443,5 @@ int LogAudit::getLogSocket() { 
        audit_close(fd);

        fd = -1;

    }

    (void)audit_rate_limit(fd, AUDIT_RATE_LIMIT_DEFAULT);

    return fd;

}

logd/LogAudit.h

+0 −6
Original line number Diff line number Diff line
@@ -18,7 +18,6 @@ 
#define _LOGD_LOG_AUDIT_H__



#include <map>

#include <queue>



#include <sysutils/SocketListener.h>
@@ -34,11 +33,6 @@ class LogAudit : public SocketListener { 
    bool events;

    bool initialized;



    bool tooFast;

    int mSock;

    std::queue<log_time> bucket;

    void checkRateLimit();



   public:

    LogAudit(LogBuffer* buf, LogReader* reader, int fdDmesg);

    int log(char* buf, size_t len);

logd/libaudit.c

+2 −21
Original line number Diff line number Diff line
@@ -160,7 +160,8 @@ int audit_setup(int fd, pid_t pid) { 
     * and the the mask set to AUDIT_STATUS_PID

     */

    status.pid = pid;

    status.mask = AUDIT_STATUS_PID;

    status.mask = AUDIT_STATUS_PID | AUDIT_STATUS_RATE_LIMIT;

    status.rate_limit = AUDIT_RATE_LIMIT; /* audit entries per second */



    /* Let the kernel know this pid will be registering for audit events */

    rc = audit_send(fd, AUDIT_SET, &status, sizeof(status));
@@ -183,26 +184,6 @@ int audit_setup(int fd, pid_t pid) { 
    return 0;

}



int audit_rate_limit(int fd, unsigned rate_limit) {

    int rc;

    struct audit_message rep;

    struct audit_status status;



    memset(&status, 0, sizeof(status));



    status.mask = AUDIT_STATUS_RATE_LIMIT;

    status.rate_limit = rate_limit; /* audit entries per second */



    rc = audit_send(fd, AUDIT_SET, &status, sizeof(status));

    if (rc < 0) {

        return rc;

    }



    audit_get_reply(fd, &rep, GET_REPLY_NONBLOCKING, 0);



    return 0;

}



int audit_open() {

    return socket(PF_NETLINK, SOCK_RAW | SOCK_CLOEXEC, NETLINK_AUDIT);

}

logd/libaudit.h

+2 −16
Original line number Diff line number Diff line
@@ -89,22 +89,8 @@ extern int audit_get_reply(int fd, struct audit_message* rep, reply_t block, 
 */

extern int audit_setup(int fd, pid_t pid);



/**

 * Sets the rate limit to receive audit netlink events from the kernel

 * @param fd

 *  The fd returned by a call to audit_open()

 * @param max_rate

 *  The cap of the maximum number of audit messages a second

 * @return

 *  This function returns 0 on success, -errno on error.

 */



/* Guidelines to follow for dynamic rate_limit */

#define AUDIT_RATE_LIMIT_DEFAULT 20        /* acceptable burst rate      */

#define AUDIT_RATE_LIMIT_BURST_DURATION 10 /* number of seconds of burst */

#define AUDIT_RATE_LIMIT_MAX 5             /* acceptable sustained rate  */



extern int audit_rate_limit(int fd, unsigned rate_limit);

/* Max audit messages per second  */

#define AUDIT_RATE_LIMIT 5



__END_DECLS

logd/tests/logd_test.cpp

+8 −45
Original line number Diff line number Diff line
@@ -1195,51 +1195,14 @@ TEST(logd, sepolicy_rate_limiter) { 
                          << "fail as this device is in a bad state, "

                          << "but is not strictly a unit test failure.";

    }

    // sepolicy_rate_limiter_maximum

    {  // maximum precharch test block.

        static constexpr int rate = AUDIT_RATE_LIMIT_MAX;

        static constexpr int duration = 2;

        // Two seconds of a liveable sustained rate

        EXPECT_EQ(rate * duration,

                  count_avc(sepolicy_rate(rate, rate * duration)));

    }

    // sepolicy_rate_limiter_sub_burst

    {  // maximum period below half way between sustainable and burst rate

        static constexpr int threshold =

            ((AUDIT_RATE_LIMIT_BURST_DURATION *

              (AUDIT_RATE_LIMIT_DEFAULT + AUDIT_RATE_LIMIT_MAX)) +

             1) /

            2;

        static constexpr int rate =

            (threshold / AUDIT_RATE_LIMIT_BURST_DURATION) - 1;

        static constexpr int duration = AUDIT_RATE_LIMIT_BURST_DURATION;

        EXPECT_EQ(rate * duration,

                  count_avc(sepolicy_rate(rate, rate * duration)));

    }

    // sepolicy_rate_limiter_spam

    {  // hit avc: hard beyond reason block.

        // maximum period of double the maximum burst rate

        static constexpr int threshold =

            ((AUDIT_RATE_LIMIT_BURST_DURATION *

              (AUDIT_RATE_LIMIT_DEFAULT + AUDIT_RATE_LIMIT_MAX)) +

             1) /

            2;

        static constexpr int rate = AUDIT_RATE_LIMIT_DEFAULT * 2;

        static constexpr int duration = threshold / AUDIT_RATE_LIMIT_DEFAULT;

        EXPECT_GE(

            ((AUDIT_RATE_LIMIT_DEFAULT * duration) * 115) / 100,  // +15% margin

            count_avc(sepolicy_rate(rate, rate * duration)));

        // give logd another 3 seconds to react to the burst before checking

        sepolicy_rate(rate, rate * 3);

        // maximum period at double maximum burst rate (spam filter kicked in)

        EXPECT_GE(threshold * 2,

                  count_avc(sepolicy_rate(

                      rate, rate * AUDIT_RATE_LIMIT_BURST_DURATION)));

        // cool down, and check unspammy rate still works

        sleep(2);

        EXPECT_LE(AUDIT_RATE_LIMIT_BURST_DURATION - 1,  // allow _one_ lost

                  count_avc(sepolicy_rate(1, AUDIT_RATE_LIMIT_BURST_DURATION)));

    }



    static const int rate = AUDIT_RATE_LIMIT;

    static const int duration = 2;

    // Two seconds of sustained denials. Depending on the overlap in the time

    // window that the kernel is considering vs what this test is considering,

    // allow some additional denials to prevent a flaky test.

    EXPECT_LE(count_avc(sepolicy_rate(rate, rate * duration)),

              rate * duration + rate);

#else

    GTEST_LOG_(INFO) << "This test does nothing.\n";

#endif