tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

logd: Add klogd

Browse source 
(cherry pick from commit ae4d928d81)

- Add a klogd to collect the kernel logs and place them into a
  new kernel log buffer
- Parse priority, tag and message from the kernel log messages.
- Turn off pruning for worst UID for the kernel log buffer
- Sniff for 'PM: suspend exit', 'PM: suspend enter' and
  'Suspended for' messages and correct the internal definition
  time correction against monotonic dynamically.
- Discern if we have monotonic or real time (delineation 1980) in
  audit messages.
- perform appropriate math to correct the timestamp to be real time
- filter out any external sources of kernel logging

Change-Id: I8d4c7c5ac19f1f3218079ee3a05a50e2ca55f60d
This commit is contained in:
Mark Salyzyn 2014-10-15 08:49:39 -07:00
parent 9e750a42b0
commit a1aacb71f3
9 changed files with 587 additions and 24 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
logd/Android.mk
View file

@ -18,6 +18,7 @@ LOCAL_SRC_FILES := \
LogWhiteBlackList.cpp \
libaudit.c \
LogAudit.cpp \
LogKlog.cpp \
event.logtags
LOCAL_SHARED_LIBRARIES := \

12
logd/LogAudit.cpp
View file

@ -29,6 +29,7 @@
#include "libaudit.h"
#include "LogAudit.h"
#include "LogKlog.h"
#define KMSG_PRIORITY(PRI) \
'<', \
@ -121,6 +122,15 @@ int LogAudit::logPrint(const char *fmt, ...) {
&& (*cp == ':')) {
memcpy(timeptr + sizeof(audit_str) - 1, "0.0", 3);
memmove(timeptr + sizeof(audit_str) - 1 + 3, cp, strlen(cp) + 1);
//
// We are either in 1970ish (MONOTONIC) or 2015+ish (REALTIME) so to
// differentiate without prejudice, we use 1980 to delineate, earlier
// is monotonic, later is real.
//
# define EPOCH_PLUS_10_YEARS (10 * 1461 / 4 * 24 * 60 * 60)
if (now.tv_sec < EPOCH_PLUS_10_YEARS) {
LogKlog::convertMonotonicToReal(now);
}
} else {
now.strptime("", ""); // side effect of setting CLOCK_REALTIME
}
@ -223,7 +233,7 @@ int LogAudit::logPrint(const char *fmt, ...) {
int LogAudit::log(char *buf) {
char *audit = strstr(buf, " audit(");
if (!audit) {
return -EXDEV;
return 0;
}
*audit = '\0';

2
logd/LogBufferElement.h
View file

@ -42,7 +42,7 @@ const char *tagToName(uint32_t tag);
}
static inline bool worstUidEnabledForLogid(log_id_t id) {
return (id != LOG_ID_CRASH) && (id != LOG_ID_EVENTS);
return (id != LOG_ID_CRASH) && (id != LOG_ID_KERNEL) && (id != LOG_ID_EVENTS);
}
class LogBuffer;

454
logd/LogKlog.cpp Normal file
View file

@ -0,0 +1,454 @@
/*
* Copyright (C) 2014 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 <ctype.h>
#include <errno.h>
#include <inttypes.h>
#include <limits.h>
#include <stdarg.h>
#include <stdlib.h>
#include <sys/prctl.h>
#include <sys/uio.h>
#include <syslog.h>
#include <log/logger.h>
#include "LogKlog.h"
#define KMSG_PRIORITY(PRI) \
'<', \
'0' + (LOG_SYSLOG | (PRI)) / 10, \
'0' + (LOG_SYSLOG | (PRI)) % 10, \
'>'
static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' };
log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC);
LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd)
: SocketListener(fdRead, false)
, logbuf(buf)
, reader(reader)
, signature(CLOCK_MONOTONIC)
, fdWrite(fdWrite)
, fdRead(fdRead)
, initialized(false)
, enableLogging(true)
, auditd(auditd) {
static const char klogd_message[] = "%slogd.klogd: %" PRIu64 "\n";
char buffer[sizeof(priority_message) + sizeof(klogd_message) + 20 - 4];
snprintf(buffer, sizeof(buffer), klogd_message, priority_message,
signature.nsec());
write(fdWrite, buffer, strlen(buffer));
}
bool LogKlog::onDataAvailable(SocketClient *cli) {
if (!initialized) {
prctl(PR_SET_NAME, "logd.klogd");
initialized = true;
enableLogging = false;
}
char buffer[LOGGER_ENTRY_MAX_PAYLOAD];
size_t len = 0;
for(;;) {
ssize_t retval = 0;
if ((sizeof(buffer) - 1 - len) > 0) {
retval = read(cli->getSocket(), buffer + len, sizeof(buffer) - 1 - len);
}
if ((retval == 0) && (len == 0)) {
break;
}
if (retval < 0) {
return false;
}
len += retval;
bool full = len == (sizeof(buffer) - 1);
char *ep = buffer + len;
*ep = '\0';
len = 0;
for(char *ptr, *tok = buffer;
((tok = strtok_r(tok, "\r\n", &ptr)));
tok = NULL) {
if (((tok + strlen(tok)) == ep) && (retval != 0) && full) {
len = strlen(tok);
memmove(buffer, tok, len);
break;
}
if (*tok) {
log(tok);
}
}
}
return true;
}
void LogKlog::calculateCorrection(const log_time &monotonic,
const char *real_string) {
log_time real;
if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) {
return;
}
// kernel report UTC, log_time::strptime is localtime from calendar.
// Bionic and liblog strptime does not support %z or %Z to pick up
// timezone so we are calculating our own correction.
time_t now = real.tv_sec;
struct tm tm;
memset(&tm, 0, sizeof(tm));
tm.tm_isdst = -1;
localtime_r(&now, &tm);
real.tv_sec += tm.tm_gmtoff;
correction = real - monotonic;
}
void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) {
const char *cp;
if ((cp = now.strptime(*buf, "[ %s.%q]"))) {
static const char suspend[] = "PM: suspend entry ";
static const char resume[] = "PM: suspend exit ";
static const char suspended[] = "Suspended for ";
if (isspace(*cp)) {
++cp;
}
if (!strncmp(cp, suspend, sizeof(suspend) - 1)) {
calculateCorrection(now, cp + sizeof(suspend) - 1);
} else if (!strncmp(cp, resume, sizeof(resume) - 1)) {
calculateCorrection(now, cp + sizeof(resume) - 1);
} else if (!strncmp(cp, suspended, sizeof(suspended) - 1)) {
log_time real;
char *endp;
real.tv_sec = strtol(cp + sizeof(suspended) - 1, &endp, 10);
if (*endp == '.') {
real.tv_nsec = strtol(endp + 1, &endp, 10) * 1000000L;
if (reverse) {
correction -= real;
} else {
correction += real;
}
}
}
convertMonotonicToReal(now);
*buf = cp;
} else {
now = log_time(CLOCK_REALTIME);
}
}
// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
// compensated start time.
void LogKlog::synchronize(const char *buf) {
const char *cp = strstr(buf, "] PM: suspend e");
if (!cp) {
return;
}
do {
--cp;
} while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.')));
log_time now;
sniffTime(now, &cp, true);
char *suspended = strstr(buf, "] Suspended for ");
if (!suspended || (suspended > cp)) {
return;
}
cp = suspended;
do {
--cp;
} while ((cp > buf) && (isdigit(*cp) || isspace(*cp) || (*cp == '.')));
sniffTime(now, &cp, true);
}
// kernel log prefix, convert to a kernel log priority number
static int parseKernelPrio(const char **buf) {
int pri = LOG_USER | LOG_INFO;
const char *cp = *buf;
if (*cp == '<') {
pri = 0;
while(isdigit(*++cp)) {
pri = (pri * 10) + *cp - '0';
}
if (*cp == '>') {
++cp;
} else {
cp = *buf;
pri = LOG_USER | LOG_INFO;
}
*buf = cp;
}
return pri;
}
// Convert kernel log priority number into an Android Logger priority number
static int convertKernelPrioToAndroidPrio(int pri) {
switch(pri & LOG_PRIMASK) {
case LOG_EMERG:
// FALLTHRU
case LOG_ALERT:
// FALLTHRU
case LOG_CRIT:
return ANDROID_LOG_FATAL;
case LOG_ERR:
return ANDROID_LOG_ERROR;
case LOG_WARNING:
return ANDROID_LOG_WARN;
default:
// FALLTHRU
case LOG_NOTICE:
// FALLTHRU
case LOG_INFO:
break;
case LOG_DEBUG:
return ANDROID_LOG_DEBUG;
}
return ANDROID_LOG_INFO;
}
//
// log a message into the kernel log buffer
//
// Filter rules to parse <PRI> <TIME> <tag> and <message> in order for
// them to appear correct in the logcat output:
//
// LOG_KERN (0):
// <PRI>[<TIME>] <tag> ":" <message>
// <PRI>[<TIME>] <tag> <tag> ":" <message>
// <PRI>[<TIME>] <tag> <tag>_work ":" <message>
// <PRI>[<TIME>] <tag> '<tag>.<num>' ":" <message>
// <PRI>[<TIME>] <tag> '<tag><num>' ":" <message>
// <PRI>[<TIME>] <tag>_host '<tag>.<num>' ":" <message>
// (unimplemented) <PRI>[<TIME>] <tag> '<num>.<tag>' ":" <message>
// <PRI>[<TIME>] "[INFO]"<tag> : <message>
// <PRI>[<TIME>] "------------[ cut here ]------------" (?)
// <PRI>[<TIME>] "---[ end trace 3225a3070ca3e4ac ]---" (?)
// LOG_USER, LOG_MAIL, LOG_DAEMON, LOG_AUTH, LOG_SYSLOG, LOG_LPR, LOG_NEWS
// LOG_UUCP, LOG_CRON, LOG_AUTHPRIV, LOG_FTP:
// <PRI+TAG>[<TIME>] (see sys/syslog.h)
// Observe:
// Minimum tag length = 3 NB: drops things like r5:c00bbadf, but allow PM:
// Maximum tag words = 2
// Maximum tag length = 16 NB: we are thinking of how ugly logcat can get.
// Not a Tag if there is no message content.
// leading additional spaces means no tag, inherit last tag.
// Not a Tag if <tag>: is "ERROR:", "WARNING:", "INFO:" or "CPU:"
// Drop:
// empty messages
// messages with ' audit(' in them if auditd is running
// logd.klogd:
// return -1 if message logd.klogd: <signature>
//
int LogKlog::log(const char *buf) {
if (auditd && strstr(buf, " audit(")) {
return 0;
}
int pri = parseKernelPrio(&buf);
log_time now;
sniffTime(now, &buf, false);
// sniff for start marker
const char klogd_message[] = "logd.klogd: ";
if (!strncmp(buf, klogd_message, sizeof(klogd_message) - 1)) {
char *endp;
uint64_t sig = strtoll(buf + sizeof(klogd_message) - 1, &endp, 10);
if (sig == signature.nsec()) {
if (initialized) {
enableLogging = true;
} else {
enableLogging = false;
}
return -1;
}
return 0;
}
if (!enableLogging) {
return 0;
}
// Parse pid, tid and uid (not possible)
const pid_t pid = 0;
const pid_t tid = 0;
const uid_t uid = 0;
// Parse (rules at top) to pull out a tag from the incoming kernel message.
// Some may view the following as an ugly heuristic, the desire is to
// beautify the kernel logs into an Android Logging format; the goal is
// admirable but costly.
while (isspace(*buf)) {
++buf;
}
if (!*buf) {
return 0;
}
const char *start = buf;
const char *tag = "";
const char *etag = tag;
if (!isspace(*buf)) {
const char *bt, *et, *cp;
bt = buf;
if (!strncmp(buf, "[INFO]", 6)) {
// <PRI>[<TIME>] "[INFO]"<tag> ":" message
bt = buf + 6;
}
for(et = bt; *et && (*et != ':') && !isspace(*et); ++et);
for(cp = et; isspace(*cp); ++cp);
size_t size;
if (*cp == ':') {
// One Word
tag = bt;
etag = et;
buf = cp + 1;
} else {
size = et - bt;
if (strncmp(bt, cp, size)) {
// <PRI>[<TIME>] <tag>_host '<tag>.<num>' : message
if (!strncmp(bt + size - 5, "_host", 5)
&& !strncmp(bt, cp, size - 5)) {
const char *b = cp;
cp += size - 5;
if (*cp == '.') {
while (!isspace(*++cp) && (*cp != ':'));
const char *e;
for(e = cp; isspace(*cp); ++cp);
if (*cp == ':') {
tag = b;
etag = e;
buf = cp + 1;
}
}
} else {
while (!isspace(*++cp) && (*cp != ':'));
const char *e;
for(e = cp; isspace(*cp); ++cp);
// Two words
if (*cp == ':') {
tag = bt;
etag = e;
buf = cp + 1;
}
}
} else if (isspace(cp[size])) {
const char *b = cp;
cp += size;
while (isspace(*++cp));
// <PRI>[<TIME>] <tag> <tag> : message
if (*cp == ':') {
tag = bt;
etag = et;
buf = cp + 1;
}
} else if (cp[size] == ':') {
// <PRI>[<TIME>] <tag> <tag> : message
tag = bt;
etag = et;
buf = cp + size + 1;
} else if ((cp[size] == '.') || isdigit(cp[size])) {
// <PRI>[<TIME>] <tag> '<tag>.<num>' : message
// <PRI>[<TIME>] <tag> '<tag><num>' : message
const char *b = cp;
cp += size;
while (!isspace(*++cp) && (*cp != ':'));
const char *e = cp;
while (isspace(*cp)) {
++cp;
}
if (*cp == ':') {
tag = b;
etag = e;
buf = cp + 1;
}
} else {
while (!isspace(*++cp) && (*cp != ':'));
const char *e = cp;
while (isspace(*cp)) {
++cp;
}
// Two words
if (*cp == ':') {
tag = bt;
etag = e;
buf = cp + 1;
}
}
}
size = etag - tag;
if ((size <= 1)
|| ((size == 2) && (isdigit(tag[0]) || isdigit(tag[1])))
|| ((size == 3) && !strncmp(tag, "CPU", 3))
|| ((size == 7) && !strncmp(tag, "WARNING", 7))
|| ((size == 5) && !strncmp(tag, "ERROR", 5))
|| ((size == 4) && !strncmp(tag, "INFO", 4))) {
buf = start;
etag = tag = "";
}
}
size_t l = etag - tag;
while (isspace(*buf)) {
++buf;
}
size_t n = 1 + l + 1 + strlen(buf) + 1;
// Allocate a buffer to hold the interpreted log message
int rc = n;
char *newstr = reinterpret_cast<char *>(malloc(n));
if (!newstr) {
rc = -ENOMEM;
return rc;
}
char *np = newstr;
// Convert priority into single-byte Android logger priority
*np = convertKernelPrioToAndroidPrio(pri);
++np;
// Copy parsed tag following priority
strncpy(np, tag, l);
np += l;
*np = '\0';
++np;
// Copy main message to the remainder
strcpy(np, buf);
// Log message
rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr,
(n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX);
free(newstr);
// notify readers
if (!rc) {
reader->notifyNewLog();
}
return rc;
}

55
logd/LogKlog.h Normal file
View file

@ -0,0 +1,55 @@
/*
* Copyright (C) 2014 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.
*/
#ifndef _LOGD_LOG_KLOG_H__
#define _LOGD_LOG_KLOG_H__
#include <sysutils/SocketListener.h>
#include <log/log_read.h>
#include "LogReader.h"
class LogKlog : public SocketListener {
LogBuffer *logbuf;
LogReader *reader;
const log_time signature;
const int fdWrite; // /dev/kmsg
const int fdRead; // /proc/kmsg
// Set once thread is started, separates KLOG_ACTION_READ_ALL
// and KLOG_ACTION_READ phases.
bool initialized;
// Used during each of the above phases to control logging.
bool enableLogging;
// set if we are also running auditd, to filter out audit reports from
// our copy of the kernel log
bool auditd;
static log_time correction;
public:
LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd);
int log(const char *buf);
void synchronize(const char *buf);
static void convertMonotonicToReal(log_time &real) { real += correction; }
protected:
void sniffTime(log_time &now, const char **buf, bool reverse);
void calculateCorrection(const log_time &monotonic, const char *real_string);
virtual bool onDataAvailable(SocketClient *cli);
};
#endif

2
logd/LogListener.cpp
View file

@ -88,7 +88,7 @@ bool LogListener::onDataAvailable(SocketClient *cli) {
}
android_log_header_t *header = reinterpret_cast<android_log_header_t *>(buffer);
if (/* header->id < LOG_ID_MIN || */ header->id >= LOG_ID_MAX) {
if (/* header->id < LOG_ID_MIN || */ header->id >= LOG_ID_MAX || header->id == LOG_ID_KERNEL) {
return false;
}

16
logd/LogStatistics.cpp
View file

@ -41,8 +41,8 @@ namespace android {
// caller must own and free character string
char *pidToName(pid_t pid) {
char *retval = NULL;
if (pid == 0) { // special case from auditd for kernel
retval = strdup("logd.auditd");
if (pid == 0) { // special case from auditd/klogd for kernel
retval = strdup("logd");
} else {
char buffer[512];
snprintf(buffer, sizeof(buffer), "/proc/%u/cmdline", pid);
@ -70,11 +70,15 @@ void LogStatistics::add(LogBufferElement *e) {
mSizes[log_id] += size;
++mElements[log_id];
uidTable[log_id].add(e->getUid(), e);
mSizesTotal[log_id] += size;
++mElementsTotal[log_id];
if (log_id == LOG_ID_KERNEL) {
return;
}
uidTable[log_id].add(e->getUid(), e);
if (!enable) {
return;
}
@ -93,6 +97,10 @@ void LogStatistics::subtract(LogBufferElement *e) {
mSizes[log_id] -= size;
--mElements[log_id];
if (log_id == LOG_ID_KERNEL) {
return;
}
uidTable[log_id].subtract(e->getUid(), e);
if (!enable) {

7
logd/README.property
View file

@ -4,9 +4,12 @@ name type default description
logd.auditd bool true Enable selinux audit daemon
logd.auditd.dmesg bool true selinux audit messages duplicated and
sent on to dmesg log
logd.klogd bool depends Enable klogd daemon
logd.statistics bool depends Enable logcat -S statistics.
ro.config.low_ram bool false if true, logd.statistics default false
ro.build.type string if user, logd.statistics default false
ro.config.low_ram bool false if true, logd.statistics & logd.klogd
default false
ro.build.type string if user, logd.statistics & logd.klogd
default false
persist.logd.size number 256K default size of the buffer for all
log ids at initial startup, at runtime
use: logcat -b all -G <value>

62
logd/main.cpp
View file

@ -42,6 +42,7 @@
#include "LogBuffer.h"
#include "LogListener.h"
#include "LogAudit.h"
#include "LogKlog.h"
#define KMSG_PRIORITY(PRI) \
'<', \
@ -256,6 +257,17 @@ const char *android::tagToName(uint32_t tag) {
return android_lookupEventTag(map, tag);
}
static bool property_get_bool_svelte(const char *key) {
bool not_user;
{
char property[PROPERTY_VALUE_MAX];
property_get("ro.build.type", property, "");
not_user = !!strcmp(property, "user");
}
return property_get_bool(key, not_user
&& !property_get_bool("ro.config.low_ram", false));
}
// Foreground waits for exit of the main persistent threads
// that are started here. The threads are created to manage
// UNIX domain client sockets for writing, reading and
@ -263,6 +275,11 @@ const char *android::tagToName(uint32_t tag) {
// logging plugins like auditd and restart control. Additional
// transitory per-client threads are created for each reader.
int main(int argc, char *argv[]) {
int fdPmesg = -1;
bool klogd = property_get_bool_svelte("logd.klogd");
if (klogd) {
fdPmesg = open("/proc/kmsg", O_RDONLY | O_NDELAY);
}
fdDmesg = open("/dev/kmsg", O_WRONLY);
// issue reinit command. KISS argument parsing.
@ -339,14 +356,8 @@ int main(int argc, char *argv[]) {
signal(SIGHUP, reinit_signal_handler);
{
char property[PROPERTY_VALUE_MAX];
property_get("ro.build.type", property, "");
if (property_get_bool("logd.statistics",
!!strcmp(property, "user")
&& !property_get_bool("ro.config.low_ram", false))) {
logBuf->enableStatistics();
}
if (property_get_bool_svelte("logd.statistics")) {
logBuf->enableStatistics();
}
// LogReader listens on /dev/socket/logdr. When a client
@ -381,12 +392,18 @@ int main(int argc, char *argv[]) {
bool auditd = property_get_bool("logd.auditd", true);
LogAudit *al = NULL;
if (auditd) {
bool dmesg = property_get_bool("logd.auditd.dmesg", true);
al = new LogAudit(logBuf, reader, dmesg ? fdDmesg : -1);
}
// failure is an option ... messages are in dmesg (required by standard)
LogAudit *al = new LogAudit(logBuf, reader, dmesg ? fdDmesg : -1);
LogKlog *kl = NULL;
if (klogd) {
kl = new LogKlog(logBuf, reader, fdDmesg, fdPmesg, al != NULL);
}
if (al || kl) {
int len = klogctl(KLOG_SIZE_BUFFER, NULL, 0);
if (len > 0) {
len++;
@ -394,16 +411,31 @@ int main(int argc, char *argv[]) {
int rc = klogctl(KLOG_READ_ALL, buf, len);
if (rc >= 0) {
buf[len - 1] = '\0';
buf[len - 1] = '\0';
for (char *ptr, *tok = buf; (tok = strtok_r(tok, "\r\n", &ptr)); tok = NULL) {
al->log(tok);
if ((rc >= 0) && kl) {
kl->synchronize(buf);
}
for (char *ptr, *tok = buf;
(rc >= 0) && ((tok = strtok_r(tok, "\r\n", &ptr)));
tok = NULL) {
if (al) {
rc = al->log(tok);
}
if (kl) {
rc = kl->log(tok);
}
}
}
if (al->startListener()) {
// failure is an option ... messages are in dmesg (required by standard)
if (kl && kl->startListener()) {
delete kl;
}
if (al && al->startListener()) {
delete al;
}
}