ACPR/android_system_core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Remove the monotonic option for logging

Browse source 
This has been around for ~5 years but there has been roughly no
adoption, so remove this as we clean up the logging code.

Future efforts may track the monotonic timestamp in all cases.

Test: logging unit tests
Change-Id: I55ed565669f923988e741f6b384141bba893630d
This commit is contained in:
Tom Cherry 2020-04-08 14:36:05 -07:00
parent 72fdec1777
commit f2c2746aba
21 changed files with 24 additions and 210 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
liblog/README.md
View file

@ -60,8 +60,6 @@ Public Functions and Macros
LOG_EVENT_INT(tag, value)
LOG_EVENT_LONG(tag, value)
clockid_t android_log_clockid()
log_id_t android_logger_get_id(struct logger *logger)
int android_logger_clear(struct logger *logger)
int android_logger_get_log_size(struct logger *logger)
@ -119,7 +117,7 @@ finally a call closing the logs. A single log can be opened with `android_logge
multiple logs can be opened with `android_logger_list_alloc()`, calling in turn the
`android_logger_open()` for each log id. Each entry can be retrieved with
`android_logger_list_read()`. The log(s) can be closed with `android_logger_list_free()`.
`ANDROID_LOG_NONBLOCK` mode will report when the log reading is done with an `EAGAIN` error return
`ANDROID_LOG_NONBLOCK` mode will report when the log reading is done with an `EAGAIN` error return
code, otherwise the `android_logger_list_read()` call will block for new entries.
The `ANDROID_LOG_WRAP` mode flag to the `android_logger_list_alloc_time()` signals logd to quiesce

6
liblog/include/log/log.h
View file

@ -133,12 +133,6 @@ typedef enum {
(void)__android_log_bswrite(_tag, _value);
#endif
#ifdef __linux__
clockid_t android_log_clockid(void);
#endif /* __linux__ */
/* --------------------------------------------------------------------- */
/*

2
liblog/logger_write.cpp
View file

@ -192,7 +192,7 @@ static int write_to_log(log_id_t log_id, struct iovec* vec, size_t nr) {
return -EINVAL;
}
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
if (log_id == LOG_ID_SECURITY) {
if (vec[0].iov_len < 4) {

15
liblog/logprint.cpp
View file

@ -216,11 +216,7 @@ AndroidLogFormat* android_log_format_new() {
p_ret->year_output = false;
p_ret->zone_output = false;
p_ret->epoch_output = false;
#ifdef __ANDROID__
p_ret->monotonic_output = android_log_clockid() == CLOCK_MONOTONIC;
#else
p_ret->monotonic_output = false;
#endif
p_ret->uid_output = false;
p_ret->descriptive_output = false;
descriptive_output = false;
@ -1465,13 +1461,10 @@ char* android_log_formatLogLine(AndroidLogFormat* p_format, char* defaultBuffer,
nsec = entry->tv_nsec;
#if __ANDROID__
if (p_format->monotonic_output) {
/* prevent convertMonotonic from being called if logd is monotonic */
if (android_log_clockid() != CLOCK_MONOTONIC) {
struct timespec time;
convertMonotonic(&time, entry);
now = time.tv_sec;
nsec = time.tv_nsec;
}
struct timespec time;
convertMonotonic(&time, entry);
now = time.tv_sec;
nsec = time.tv_nsec;
}
#endif
if (now < 0) {

2
liblog/pmsg_writer.cpp
View file

@ -188,7 +188,7 @@ ssize_t __android_log_pmsg_file_write(log_id_t logId, char prio, const char* fil
return -EINVAL;
}
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
cp = strdup(filename);
if (!cp) {

23
liblog/properties.cpp
View file

@ -365,29 +365,6 @@ static inline unsigned char do_cache2_char(struct cache2_char* self) {
return c;
}
static unsigned char evaluate_persist_ro(const struct cache2_char* self) {
unsigned char c = self->cache_persist.c;
if (c) {
return c;
}
return self->cache_ro.c;
}
/*
* Timestamp state generally remains constant, but can change at any time
* to handle developer requirements.
*/
clockid_t android_log_clockid() {
static struct cache2_char clockid = {PTHREAD_MUTEX_INITIALIZER, 0,
"persist.logd.timestamp", {{NULL, 0xFFFFFFFF}, '\0'},
"ro.logd.timestamp", {{NULL, 0xFFFFFFFF}, '\0'},
evaluate_persist_ro};
return (tolower(do_cache2_char(&clockid)) == 'm') ? CLOCK_MONOTONIC : CLOCK_REALTIME;
}
/*
* Security state generally remains constant, but the DO must be able
* to turn off logging should it become spammy after an attack is detected.

20
liblog/tests/liblog_benchmark.cpp
View file

@ -184,7 +184,7 @@ static void BM_pmsg_short(benchmark::State& state) {
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
android_pmsg_log_header_t pmsg_header;
pmsg_header.magic = LOGGER_MAGIC;
@ -260,7 +260,7 @@ static void BM_pmsg_short_aligned(benchmark::State& state) {
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
struct packet {
android_pmsg_log_header_t pmsg_header;
@ -335,7 +335,7 @@ static void BM_pmsg_short_unaligned1(benchmark::State& state) {
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
struct packet {
android_pmsg_log_header_t pmsg_header;
@ -410,7 +410,7 @@ static void BM_pmsg_long_aligned(benchmark::State& state) {
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
struct packet {
android_pmsg_log_header_t pmsg_header;
@ -483,7 +483,7 @@ static void BM_pmsg_long_unaligned1(benchmark::State& state) {
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
struct packet {
android_pmsg_log_header_t pmsg_header;
@ -791,16 +791,6 @@ static void BM_is_loggable(benchmark::State& state) {
}
BENCHMARK(BM_is_loggable);
/*
* Measure the time it takes for android_log_clockid.
*/
static void BM_clockid(benchmark::State& state) {
while (state.KeepRunning()) {
android_log_clockid();
}
}
BENCHMARK(BM_clockid);
/*
* Measure the time it takes for __android_log_security.
*/

3
liblog/tests/liblog_test.cpp
View file

@ -329,8 +329,6 @@ static void bswrite_test(const char* message) {
#ifdef __ANDROID__
pid_t pid = getpid();
log_time ts(android_log_clockid());
size_t num_lines = 1, size = 0, length = 0, total = 0;
const char* cp = message;
while (*cp) {
@ -432,7 +430,6 @@ static void buf_write_test(const char* message) {
pid_t pid = getpid();
static const char tag[] = "TEST__android_log_buf_write";
log_time ts(android_log_clockid());
auto write_function = [&] {
EXPECT_LT(0, __android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_INFO, tag, message));

2
logcat/logcat.cpp
View file

@ -459,7 +459,7 @@ static log_time lastLogTime(const char* outputFileName) {
closedir);
if (!dir.get()) return retval;
log_time now(android_log_clockid());
log_time now(CLOCK_REALTIME);
size_t len = strlen(file);
log_time modulo(0, NS_PER_SEC);

10
logcat/tests/logcat_test.cpp
View file

@ -174,11 +174,6 @@ static size_t inject(ssize_t count) {
}
TEST(logcat, year) {
if (android_log_clockid() == CLOCK_MONOTONIC) {
fprintf(stderr, "Skipping test, logd is monotonic time\n");
return;
}
int count;
int tries = 3; // in case run too soon after system start or buffer clear
@ -249,11 +244,6 @@ static char* fgetLongTime(char* buffer, size_t buflen, FILE* fp) {
}
TEST(logcat, tz) {
if (android_log_clockid() == CLOCK_MONOTONIC) {
fprintf(stderr, "Skipping test, logd is monotonic time\n");
return;
}
int tries = 4; // in case run too soon after system start or buffer clear
int count;

15
logd/LogAudit.cpp
View file

@ -247,22 +247,13 @@ int LogAudit::logPrint(const char* fmt, ...) {
static const char audit_str[] = " audit(";
char* timeptr = strstr(str, audit_str);
if (timeptr &&
((cp = now.strptime(timeptr + sizeof(audit_str) - 1, "%s.%q"))) &&
if (timeptr && ((cp = now.strptime(timeptr + sizeof(audit_str) - 1, "%s.%q"))) &&
(*cp == ':')) {
memcpy(timeptr + sizeof(audit_str) - 1, "0.0", 3);
memmove(timeptr + sizeof(audit_str) - 1 + 3, cp, strlen(cp) + 1);
if (!isMonotonic()) {
if (android::isMonotonic(now)) {
LogKlog::convertMonotonicToReal(now);
}
} else {
if (!android::isMonotonic(now)) {
LogKlog::convertRealToMonotonic(now);
}
if (android::isMonotonic(now)) {
LogKlog::convertMonotonicToReal(now);
}
} else if (isMonotonic()) {
now = log_time(CLOCK_MONOTONIC);
} else {
now = log_time(CLOCK_REALTIME);
}

3
logd/LogAudit.h
View file

@ -36,9 +36,6 @@ class LogAudit : public SocketListener {
public:
LogAudit(LogBuffer* buf, LogReader* reader, int fdDmesg);
int log(char* buf, size_t len);
bool isMonotonic() {
return logbuf->isMonotonic();
}
protected:
virtual bool onDataAvailable(SocketClient* cli);

47
logd/LogBuffer.cpp
View file

@ -50,48 +50,6 @@ void LogBuffer::init() {
setSize(i, LOG_BUFFER_MIN_SIZE);
}
}
bool lastMonotonic = monotonic;
monotonic = android_log_clockid() == CLOCK_MONOTONIC;
if (lastMonotonic != monotonic) {
//
// Fixup all timestamps, may not be 100% accurate, but better than
// throwing what we have away when we get 'surprised' by a change.
// In-place element fixup so no need to check reader-lock. Entries
// should already be in timestamp order, but we could end up with a
// few out-of-order entries if new monotonics come in before we
// are notified of the reinit change in status. A Typical example would
// be:
// --------- beginning of system
// 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
// --------- beginning of kernel
// 0.000000 0 0 I : Initializing cgroup subsys
// as the act of mounting /data would trigger persist.logd.timestamp to
// be corrected. 1/30 corner case YMMV.
//
rdlock();
LogBufferElementCollection::iterator it = mLogElements.begin();
while ((it != mLogElements.end())) {
LogBufferElement* e = *it;
if (monotonic) {
if (!android::isMonotonic(e->mRealTime)) {
LogKlog::convertRealToMonotonic(e->mRealTime);
if ((e->mRealTime.tv_nsec % 1000) == 0) {
e->mRealTime.tv_nsec++;
}
}
} else {
if (android::isMonotonic(e->mRealTime)) {
LogKlog::convertMonotonicToReal(e->mRealTime);
if ((e->mRealTime.tv_nsec % 1000) == 0) {
e->mRealTime.tv_nsec++;
}
}
}
++it;
}
unlock();
}
// Release any sleeping reader threads to dump their current content.
LogReaderThread::wrlock();
@ -106,10 +64,7 @@ void LogBuffer::init() {
}
LogBuffer::LogBuffer(LastLogTimes* times, LogTags* tags, PruneList* prune)
: monotonic(android_log_clockid() == CLOCK_MONOTONIC),
mTimes(*times),
tags_(tags),
prune_(prune) {
: mTimes(*times), tags_(tags), prune_(prune) {
pthread_rwlock_init(&mLogElementsLock, nullptr);
log_id_for_each(i) {

5
logd/LogBuffer.h
View file

@ -91,8 +91,6 @@ class LogBuffer {
unsigned long mMaxSize[LOG_ID_MAX];
bool monotonic;
LogBufferElement* lastLoggedElements[LOG_ID_MAX];
LogBufferElement* droppedElements[LOG_ID_MAX];
void log(LogBufferElement* elem);
@ -103,9 +101,6 @@ class LogBuffer {
LogBuffer(LastLogTimes* times, LogTags* tags, PruneList* prune);
~LogBuffer();
void init();
bool isMonotonic() {
return monotonic;
}
int log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, const char* msg,
uint16_t len);

49
logd/LogKlog.cpp
View file

@ -309,8 +309,6 @@ log_time LogKlog::sniffTime(const char*& buf, ssize_t len, bool reverse) {
}
buf = cp;
if (isMonotonic()) return now;
const char* b;
if (((b = android::strnstr(cp, len, suspendStr))) &&
(((b += strlen(suspendStr)) - cp) < len)) {
@ -356,11 +354,7 @@ log_time LogKlog::sniffTime(const char*& buf, ssize_t len, bool reverse) {
convertMonotonicToReal(now);
} else {
if (isMonotonic()) {
now = log_time(CLOCK_MONOTONIC);
} else {
now = log_time(CLOCK_REALTIME);
}
now = log_time(CLOCK_REALTIME);
}
return now;
}
@ -431,45 +425,6 @@ static int parseKernelPrio(const char*& buf, ssize_t len) {
return pri;
}
// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
// compensated start time.
void LogKlog::synchronize(const char* buf, ssize_t len) {
const char* cp = android::strnstr(buf, len, suspendStr);
if (!cp) {
cp = android::strnstr(buf, len, resumeStr);
if (!cp) return;
} else {
const char* rp = android::strnstr(buf, len, resumeStr);
if (rp && (rp < cp)) cp = rp;
}
do {
--cp;
} while ((cp > buf) && (*cp != '\n'));
if (*cp == '\n') {
++cp;
}
parseKernelPrio(cp, len - (cp - buf));
log_time now = sniffTime(cp, len - (cp - buf), true);
const char* suspended = android::strnstr(buf, len, suspendedStr);
if (!suspended || (suspended > cp)) {
return;
}
cp = suspended;
do {
--cp;
} while ((cp > buf) && (*cp != '\n'));
if (*cp == '\n') {
++cp;
}
parseKernelPrio(cp, len - (cp - buf));
sniffTime(cp, len - (cp - buf), true);
}
// Convert kernel log priority number into an Android Logger priority number
static int convertKernelPrioToAndroidPrio(int pri) {
switch (pri & LOG_PRIMASK) {
@ -789,7 +744,7 @@ int LogKlog::log(const char* buf, ssize_t len) {
memcpy(np, p, b);
np[b] = '\0';
if (!isMonotonic()) {
{
// Watch out for singular race conditions with timezone causing near
// integer quarter-hour jumps in the time and compensate accordingly.
// Entries will be temporal within near_seconds * 2. b/21868540

7
logd/LogKlog.h
View file

@ -42,17 +42,10 @@ class LogKlog : public SocketListener {
LogKlog(LogBuffer* buf, LogReader* reader, int fdWrite, int fdRead,
bool auditd);
int log(const char* buf, ssize_t len);
void synchronize(const char* buf, ssize_t len);
bool isMonotonic() {
return logbuf->isMonotonic();
}
static void convertMonotonicToReal(log_time& real) {
real += correction;
}
static void convertRealToMonotonic(log_time& real) {
real -= correction;
}
protected:
log_time sniffTime(const char*& buf, ssize_t len, bool reverse);

7
logd/LogReader.cpp
View file

@ -150,9 +150,8 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
// Convert realtime to sequence number
if (start != log_time::EPOCH) {
bool start_time_set = false;
bool is_monotonic = logbuf().isMonotonic() && android::isMonotonic(start);
uint64_t last = sequence;
auto log_find_start = [pid, logMask, start, is_monotonic, &sequence, &start_time_set,
auto log_find_start = [pid, logMask, start, &sequence, &start_time_set,
&last](const LogBufferElement* element) -> int {
if (pid && pid != element->getPid()) {
return 0;
@ -164,15 +163,13 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
sequence = element->getSequence();
start_time_set = true;
return -1;
} else if (!is_monotonic || android::isMonotonic(element->getRealTime())) {
} else {
if (start < element->getRealTime()) {
sequence = last;
start_time_set = true;
return -1;
}
last = element->getSequence();
} else {
last = element->getSequence();
}
return 0;
};

2
logd/LogTags.cpp
View file

@ -548,7 +548,7 @@ void LogTags::WritePmsgEventLogTags(uint32_t tag, uid_t uid) {
*/
struct timespec ts;
clock_gettime(android_log_clockid(), &ts);
clock_gettime(CLOCK_REALTIME, &ts);
android_log_header_t header = {
.id = LOG_ID_EVENTS,

4
logd/README.property
View file

@ -44,10 +44,6 @@ ro.logd.filter string "~! ~1000/!" default for persist.logd.filter.
oldest entries of chattiest UID, and
the chattiest PID of system
(1000, or AID_SYSTEM).
persist.logd.timestamp string ro The recording timestamp source.
"m[onotonic]" is the only supported
key character, otherwise realtime.
ro.logd.timestamp string realtime default for persist.logd.timestamp
log.tag string persist The global logging level, VERBOSE,
DEBUG, INFO, WARN, ERROR, ASSERT or
SILENT. Only the first character is

4
logd/main.cpp
View file

@ -201,10 +201,6 @@ static void readDmesg(LogAudit* al, LogKlog* kl) {
}
buf[--len] = '\0';
if (kl && kl->isMonotonic()) {
kl->synchronize(buf.get(), len);
}
ssize_t sublen;
for (char *ptr = nullptr, *tok = buf.get();
(rc >= 0) && !!(tok = android::log_strntok_r(tok, len, ptr, sublen));

4
logd/tests/logd_test.cpp
View file

@ -606,7 +606,7 @@ TEST(logd, timeout) {
// A few tries to get it right just in case wrap kicks in due to
// content providers being active during the test.
int i = 5;
log_time start(android_log_clockid());
log_time start(CLOCK_REALTIME);
start.tv_sec -= 30; // reach back a moderate period of time
while (--i) {
@ -682,7 +682,7 @@ TEST(logd, timeout) {
if (msg > start) {
start = msg;
start.tv_sec += 30;
log_time now = log_time(android_log_clockid());
log_time now = log_time(CLOCK_REALTIME);
if (start > now) {
start = now;
--start.tv_sec;