From fc148f7f3371ccc0584261dd0b2462c09798d4f8 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 14 Dec 2016 12:52:50 -0800 Subject: [PATCH] liblog: add IF_ALOG_RATELIMIT IF_ALOG_RATELIMIT() ALOGE("Only one message globally using IF_ALOG_RATELIMIT()" " in the process may appear ever ten seconds," " (%s)", strerror(errno)); static time_t last; /* initial state zero */ IF_ALOG_RATELIMIT_LOCAL(60, &last) ALOGE("Only one message locally may appear every minute," " (%s)", strerror(errno)); These new calls are guaranteed not to affect the value of a non-zero errno to simplify logging of errors. However, the ALOGE calls in the above examples may update the errno value upon their return. Test: gTest liblog-unit-tests --gtest_filter=liblog.__android_log_ratelimit Bug: 33535908 Change-Id: Id8cc192fc7d14504ffd418933cf88ae945c089f2 --- include/log/log.h | 50 ++++++++++++++++++++- liblog/Android.bp | 1 + liblog/log_ratelimit.cpp | 86 ++++++++++++++++++++++++++++++++++++ liblog/tests/liblog_test.cpp | 32 ++++++++++++++ 4 files changed, 168 insertions(+), 1 deletion(-) create mode 100644 liblog/log_ratelimit.cpp diff --git a/include/log/log.h b/include/log/log.h index d6f0eb524..ece9ea6d1 100644 --- a/include/log/log.h +++ b/include/log/log.h @@ -24,7 +24,7 @@ #include /* uint16_t, int32_t */ #include #include -#include /* clock_gettime */ +#include #include #include @@ -812,6 +812,54 @@ int __android_log_error_write(int tag, const char* subTag, int32_t uid, void __android_log_close(); #endif +#ifndef __ANDROID_USE_LIBLOG_RATELIMIT_INTERFACE +#ifndef __ANDROID_API__ +#define __ANDROID_USE_LIBLOG_RATELIMIT_INTERFACE 1 +#elif __ANDROID_API__ > 25 /* > OC */ +#define __ANDROID_USE_LIBLOG_RATELIMIT_INTERFACE 1 +#else +#define __ANDROID_USE_LIBLOG_RATELIMIT_INTERFACE 0 +#endif +#endif + +#if __ANDROID_USE_LIBLOG_RATELIMIT_INTERFACE + +/* + * if last is NULL, caller _must_ provide a consistent value for seconds. + * + * Return -1 if we can not acquire a lock, which below will permit the logging, + * error on allowing a log message through. + */ +int __android_log_ratelimit(time_t seconds, time_t* last); + +/* + * Usage: + * + * // Global default and state + * IF_ALOG_RATELIMIT() { + * ALOG*(...); + * } + * + * // local state, 10 seconds ratelimit + * static time_t local_state; + * IF_ALOG_RATELIMIT_LOCAL(10, &local_state) { + * ALOG*(...); + * } + */ + +#define IF_ALOG_RATELIMIT() \ + if (__android_log_ratelimit(0, NULL) > 0) +#define IF_ALOG_RATELIMIT_LOCAL(seconds, state) \ + if (__android_log_ratelimit(seconds, state) > 0) + +#else + +/* No ratelimiting as API unsupported */ +#define IF_ALOG_RATELIMIT() if (1) +#define IF_ALOG_RATELIMIT_LOCAL(...) if (1) + +#endif + #if defined(__clang__) #pragma clang diagnostic pop #endif diff --git a/liblog/Android.bp b/liblog/Android.bp index 2424dba75..be47fc333 100644 --- a/liblog/Android.bp +++ b/liblog/Android.bp @@ -21,6 +21,7 @@ liblog_sources = [ "config_write.c", "logger_name.c", "logger_lock.c", + "log_ratelimit.cpp", ] liblog_host_sources = [ "fake_log_device.c", diff --git a/liblog/log_ratelimit.cpp b/liblog/log_ratelimit.cpp new file mode 100644 index 000000000..dfd4b8fcc --- /dev/null +++ b/liblog/log_ratelimit.cpp @@ -0,0 +1,86 @@ +/* +** Copyright 2016, The Android Open Source Project +** +** Licensed under the Apache License, Version 2.0 (the "License"); +** you may not use this file except in compliance with the License. +** You may obtain a copy of the License at +** +** http://www.apache.org/licenses/LICENSE-2.0 +** +** Unless required by applicable law or agreed to in writing, software +** distributed under the License is distributed on an "AS IS" BASIS, +** WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +** See the License for the specific language governing permissions and +** limitations under the License. +*/ + +#include +#include +#include + +#include + +#include "log_portability.h" + +// Global default if 'last' argument in __android_log_ratelimit is NULL +static time_t g_last_clock; +// Global above can not deal well with callers playing games with the +// seconds argument, so we will also hold on to the maximum value +// ever provided and use that to gain consistency. If the caller +// provides their own 'last' argument, then they can play such games +// of varying the 'seconds' argument to their pleasure. +static time_t g_last_seconds; +static const time_t last_seconds_default = 10; +static const time_t last_seconds_max = 24 * 60 * 60; // maximum of a day +static const time_t last_seconds_min = 2; // granularity +// Lock to protect last_clock and last_seconds, but also 'last' +// argument (not NULL) as supplied to __android_log_ratelimit. +static pthread_mutex_t lock_ratelimit = PTHREAD_MUTEX_INITIALIZER; + +// if last is NULL, caller _must_ provide a consistent value for +// seconds, otherwise we will take the maximum ever issued and hold +// on to that. Preserves value of non-zero errno. Return -1 if we +// can not acquire a lock, 0 if we are not to log a message, and 1 +// if we are ok to log a message. Caller should check > 0 for true. +LIBLOG_ABI_PUBLIC int __android_log_ratelimit(time_t seconds, time_t* last) { + int save_errno = errno; + + // Two reasons for trylock failure: + // 1. In a signal handler. Must prevent deadlock + // 2. Too many threads calling __android_log_ratelimit. + // Bonus to not print if they race here because that + // dovetails the goal of ratelimiting. One may print + // and the others will wait their turn ... + if (pthread_mutex_trylock(&lock_ratelimit)) { + if (save_errno) errno = save_errno; + return -1; + } + + if (seconds == 0) { + seconds = last_seconds_default; + } else if (seconds < last_seconds_min) { + seconds = last_seconds_min; + } else if (seconds > last_seconds_max) { + seconds = last_seconds_max; + } + + if (!last) { + if (g_last_seconds > seconds) { + seconds = g_last_seconds; + } else if (g_last_seconds < seconds) { + g_last_seconds = seconds; + } + last = &g_last_clock; + } + + time_t now = time(NULL); + if ((now == (time_t)-1) || ((*last + seconds) > now)) { + pthread_mutex_unlock(&lock_ratelimit); + if (save_errno) errno = save_errno; + return 0; + } + *last = now; + pthread_mutex_unlock(&lock_ratelimit); + if (save_errno) errno = save_errno; + return 1; +} diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index d07d77430..01a562c9f 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -2870,3 +2870,35 @@ TEST(liblog, event_log_tags) { GTEST_LOG_(INFO) << "This test does nothing.\n"; #endif } + +TEST(liblog, __android_log_ratelimit) { + time_t state = 0; + + errno = 42; + // Prime + __android_log_ratelimit(3, &state); + EXPECT_EQ(errno, 42); + // Check + EXPECT_FALSE(__android_log_ratelimit(3, &state)); + sleep(1); + EXPECT_FALSE(__android_log_ratelimit(3, &state)); + sleep(4); + EXPECT_TRUE(__android_log_ratelimit(3, &state)); + sleep(5); + EXPECT_TRUE(__android_log_ratelimit(3, &state)); + + // API checks + IF_ALOG_RATELIMIT_LOCAL(3, &state) { + EXPECT_FALSE(0 != "IF_ALOG_RATELIMIT_LOCAL(3, &state)"); + } + + IF_ALOG_RATELIMIT() { + ; + } else { + EXPECT_TRUE(0 == "IF_ALOG_RATELIMIT()"); + } + IF_ALOG_RATELIMIT() { + EXPECT_FALSE(0 != "IF_ALOG_RATELIMIT()"); + } + // Do not test default seconds, to allow liblog to tune freely +}