From 61e9ce6709a12cf39a9471476da3d50339efe466 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 12 Sep 2016 14:51:54 -0700 Subject: [PATCH] logd: add getEventTag command and service Will register a new event tag by name and format, and return an event-log-tags format response with the newly allocated tag. If format is not specified, then nothing will be recorded, but a pre-existing named entry will be listed. If name and format are not specified, list all dynamic entries. If name=* list all event log tag entries. Stickiness through logd crash will be managed with the tmpfs file /dev/event-log-tags and through a reboot with add_tag entries in the pmsg last logcat event log. On debug builds we retain a /data/misc/logd/event-log-tags file that aids stickiness and that can be picked up by the bugreport. If we detect truncation damage to /dev/event-log-tags, or to /data/misc/logd/event-log-tags, rebuild file with a new first line signature incorporating the time so mmap'd readers of the file can detect the possible change in shape and order. Manual testing: Make sure nc (netcat) is built for the target platform on the host: $ m nc Then the following can be used to issue a request on the platform: $ echo -n 'getEventTag name= format=""\0EXIT\0' | > nc -U /dev/socket/logd Test: gTest logd-unit-test --gtest_filter=getEventTag* Bug: 31456426 Change-Id: I5dacc5f84a24d52dae09cca5ee1a3a9f9207f06d --- logd/Android.mk | 14 +- logd/CommandListener.cpp | 37 ++ logd/CommandListener.h | 1 + logd/LogBuffer.cpp | 6 +- logd/LogBuffer.h | 9 + logd/LogStatistics.cpp | 7 +- logd/LogStatistics.h | 2 +- logd/LogTags.cpp | 884 +++++++++++++++++++++++++++++++++++++++ logd/LogTags.h | 118 ++++++ logd/LogUtils.h | 5 +- logd/event.logtags | 1 + logd/logd.rc | 7 + logd/logtagd.rc | 9 + logd/main.cpp | 21 +- logd/tests/logd_test.cpp | 53 ++- 15 files changed, 1138 insertions(+), 36 deletions(-) create mode 100644 logd/LogTags.cpp create mode 100644 logd/LogTags.h create mode 100644 logd/logtagd.rc diff --git a/logd/Android.mk b/logd/Android.mk index 2da9782f7..9211037bb 100644 --- a/logd/Android.mk +++ b/logd/Android.mk @@ -21,6 +21,7 @@ LOCAL_SRC_FILES := \ libaudit.c \ LogAudit.cpp \ LogKlog.cpp \ + LogTags.cpp \ event.logtags LOCAL_SHARED_LIBRARIES := \ @@ -38,12 +39,23 @@ LOCAL_SHARED_LIBRARIES := \ # $(LOCAL_PATH)/$2/event.logtags) # event_flag := $(call event_logtags,auditd) # event_flag += $(call event_logtags,logd) +# event_flag += $(call event_logtags,tag_def) # so make sure we do not regret hard-coding it as follows: -event_flag := -DAUDITD_LOG_TAG=1003 -DCHATTY_LOG_TAG=1004 +event_flag := -DAUDITD_LOG_TAG=1003 -DCHATTY_LOG_TAG=1004 -DTAG_DEF_LOG_TAG=1005 event_flag += -DLIBLOG_LOG_TAG=1006 LOCAL_CFLAGS := -Werror $(event_flag) include $(BUILD_EXECUTABLE) +include $(CLEAR_VARS) + +LOCAL_MODULE := logtagd.rc +LOCAL_SRC_FILES := $(LOCAL_MODULE) +LOCAL_MODULE_CLASS := ETC +LOCAL_MODULE_TAGS := debug +LOCAL_MODULE_PATH := $(TARGET_OUT_ETC)/init + +include $(BUILD_PREBUILT) + include $(call first-makefiles-under,$(LOCAL_PATH)) diff --git a/logd/CommandListener.cpp b/logd/CommandListener.cpp index 52c67424a..74e0ea576 100644 --- a/logd/CommandListener.cpp +++ b/logd/CommandListener.cpp @@ -15,6 +15,7 @@ */ #include +#include #include #include #include @@ -47,6 +48,7 @@ CommandListener::CommandListener(LogBuffer *buf, LogReader * /*reader*/, registerCmd(new GetStatisticsCmd(buf)); registerCmd(new SetPruneListCmd(buf)); registerCmd(new GetPruneListCmd(buf)); + registerCmd(new GetEventTagCmd(buf)); registerCmd(new ReinitCmd()); registerCmd(new ExitCmd(this)); } @@ -284,6 +286,41 @@ int CommandListener::SetPruneListCmd::runCommand(SocketClient *cli, return 0; } +CommandListener::GetEventTagCmd::GetEventTagCmd(LogBuffer *buf) : + LogCommand("getEventTag"), + mBuf(*buf) { +} + +int CommandListener::GetEventTagCmd::runCommand(SocketClient *cli, + int argc, char ** argv) { + setname(); + uid_t uid = cli->getUid(); + if (clientHasLogCredentials(cli)) { + uid = AID_ROOT; + } + + const char *name = NULL; + const char *format = NULL; + for (int i = 1; i < argc; ++i) { + static const char _name[] = "name="; + if (!strncmp(argv[i], _name, strlen(_name))) { + name = argv[i] + strlen(_name); + continue; + } + + static const char _format[] = "format="; + if (!strncmp(argv[i], _format, strlen(_format))) { + format = argv[i] + strlen(_format); + continue; + } + } + + cli->sendMsg(package_string(mBuf.formatGetEventTag(uid, + name, format)).c_str()); + + return 0; +} + CommandListener::ReinitCmd::ReinitCmd() : LogCommand("reinit") { } diff --git a/logd/CommandListener.h b/logd/CommandListener.h index 5d5017785..39de03b5a 100644 --- a/logd/CommandListener.h +++ b/logd/CommandListener.h @@ -61,6 +61,7 @@ private: LogBufferCmd(GetStatistics); LogBufferCmd(GetPruneList); LogBufferCmd(SetPruneList); + LogBufferCmd(GetEventTag); #define LogCmd(name) \ class name##Cmd : public LogCommand { \ diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 820ff64d1..7613c1e98 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -199,15 +199,13 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, if (log_id != LOG_ID_SECURITY) { int prio = ANDROID_LOG_INFO; const char *tag = NULL; - size_t len = 0; if (log_id == LOG_ID_EVENTS) { - tag = android::tagToName(&len, elem->getTag()); + tag = tagToName(elem->getTag()); } else { prio = *msg; tag = msg + 1; - len = strlen(tag); } - if (!__android_log_is_loggable_len(prio, tag, len, ANDROID_LOG_VERBOSE)) { + if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) { // Log traffic received to total pthread_mutex_lock(&mLogElementsLock); stats.add(elem); diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 932d55f9a..da63e125e 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -27,6 +27,7 @@ #include #include "LogBufferElement.h" +#include "LogTags.h" #include "LogTimes.h" #include "LogStatistics.h" #include "LogWhiteBlackList.h" @@ -99,6 +100,8 @@ class LogBuffer { bool monotonic; + LogTags tags; + LogBufferElement* lastLoggedElements[LOG_ID_MAX]; LogBufferElement* droppedElements[LOG_ID_MAX]; void log(LogBufferElement* elem); @@ -133,6 +136,12 @@ public: int initPrune(const char *cp) { return mPrune.init(cp); } std::string formatPrune() { return mPrune.format(); } + std::string formatGetEventTag(uid_t uid, + const char *name, const char *format) { + return tags.formatGetEventTag(uid, name, format); + } + const char *tagToName(uint32_t tag) { return tags.tagToName(tag); } + // helper must be protected directly or implicitly by lock()/unlock() const char *pidToName(pid_t pid) { return stats.pidToName(pid); } uid_t pidToUid(pid_t pid) { return stats.pidToUid(pid); } diff --git a/logd/LogStatistics.cpp b/logd/LogStatistics.cpp index 273150e7d..7e0a6b7e1 100644 --- a/logd/LogStatistics.cpp +++ b/logd/LogStatistics.cpp @@ -452,12 +452,11 @@ std::string TagEntry::format(const LogStatistics & /* stat */, log_id_t /* id */ name = android::base::StringPrintf("%7u/%u", getKey(), uid); } - size_t len = 0; - const char *nameTmp = getName(len); + const char *nameTmp = getName(); if (nameTmp) { name += android::base::StringPrintf( - "%*s%.*s", (int)std::max(14 - name.length(), (size_t)1), - "", (int)len, nameTmp); + "%*s%s", (int)std::max(14 - name.length(), (size_t)1), + "", nameTmp); } std::string size = android::base::StringPrintf("%zu", diff --git a/logd/LogStatistics.h b/logd/LogStatistics.h index 7acef6d6c..777dc33a5 100644 --- a/logd/LogStatistics.h +++ b/logd/LogStatistics.h @@ -413,7 +413,7 @@ struct TagEntry : public EntryBaseDropped { const uint32_t&getKey() const { return tag; } const pid_t&getPid() const { return pid; } const uid_t&getUid() const { return uid; } - const char*getName(size_t &len) const { return android::tagToName(&len, tag); } + const char*getName() const { return android::tagToName(tag); } inline void add(LogBufferElement *element) { if (uid != element->getUid()) { diff --git a/logd/LogTags.cpp b/logd/LogTags.cpp new file mode 100644 index 000000000..a109592ba --- /dev/null +++ b/logd/LogTags.cpp @@ -0,0 +1,884 @@ +/* + * Copyright (C) 2017 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 +#include +#include +#include +#include +#include +#include + +#include + +#include +#include +#include +#include +#include +#include + +#include "LogTags.h" +#include "LogUtils.h" + +static LogTags* logtags; + +const char LogTags::system_event_log_tags[] = "/system/etc/event-log-tags"; +const char LogTags::dynamic_event_log_tags[] = "/dev/event-log-tags"; +// Only for debug +const char LogTags::debug_event_log_tags[] = "/data/misc/logd/event-log-tags"; + +// Sniff for first uid=%d in utf8z comment string +static uid_t sniffUid(const char* comment, const char* endp) { + if (!comment) return AID_ROOT; + + if (*comment == '#') ++comment; + while ((comment < endp) && (*comment != '\n') && isspace(*comment)) ++comment; + static const char uid_str[] = "uid="; + if (((comment + strlen(uid_str)) >= endp) || + fastcmp(comment, uid_str, strlen(uid_str)) || + !isdigit(comment[strlen(uid_str)])) return AID_ROOT; + char* cp; + unsigned long Uid = strtoul(comment + 4, &cp, 10); + if ((cp > endp) || (Uid >= INT_MAX)) return AID_ROOT; + + return Uid; +} + +// Checks for file corruption, and report false if there was no need +// to rebuild the referenced file. Failure to rebuild is only logged, +// does not cause a return value of false. +bool LogTags::RebuildFileEventLogTags(const char* filename, bool warn) { + int fd; + + { + android::RWLock::AutoRLock readLock(rwlock); + + if (tag2total.begin() == tag2total.end()) { + return false; + } + + file2watermark_const_iterator iwater = file2watermark.find(filename); + if (iwater == file2watermark.end()) { + return false; + } + + struct stat sb; + if (!stat(filename, &sb) && ((size_t)sb.st_size >= iwater->second)) { + return false; + } + + // dump what we already know back into the file? + fd = TEMP_FAILURE_RETRY(open(filename, + O_WRONLY | O_TRUNC | O_CLOEXEC | + O_NOFOLLOW | O_BINARY)); + if (fd >= 0) { + time_t now = time(NULL); + struct tm tm; + localtime_r(&now, &tm); + char timebuf[20]; + size_t len = strftime(timebuf, sizeof(timebuf), + "%Y-%m-%d %H:%M:%S", &tm); + android::base::WriteStringToFd( + android::base::StringPrintf( + "# Rebuilt %.20s, content owned by logd\n", timebuf), + fd); + for (const auto& it : tag2total) { + android::base::WriteStringToFd(formatEntry_locked(it.first, + AID_ROOT), + fd); + } + TEMP_FAILURE_RETRY(close(fd)); + } + } + + if (warn) { + android::prdebug(((fd < 0) ? + "%s failed to rebuild" : + "%s missing, damaged or truncated; rebuilt"), + filename); + } + + if (fd >= 0) { + android::RWLock::AutoWLock writeLock(rwlock); + + struct stat sb; + if (!stat(filename, &sb)) file2watermark[filename] = sb.st_size; + } + + return true; +} + +void LogTags::AddEventLogTags(uint32_t tag, uid_t uid, + const std::string& Name, + const std::string& Format, + const char* source, bool warn) { + std::string Key = Name; + if (Format.length()) Key += "+" + Format; + + bool update = !source || !!strcmp(source, system_event_log_tags); + bool newOne; + + { + android::RWLock::AutoWLock writeLock(rwlock); + + tag2total_const_iterator itot = tag2total.find(tag); + + // unlikely except for dupes, or updates to uid list (more later) + if (itot != tag2total.end()) update = false; + + newOne = tag2name.find(tag) == tag2name.end(); + key2tag[Key] = tag; + + if (Format.length()) { + if (key2tag.find(Name) == key2tag.end()) { + key2tag[Name] = tag; + } + tag2format[tag] = Format; + } + tag2name[tag] = Name; + + tag2uid_const_iterator ut = tag2uid.find(tag); + if (ut != tag2uid.end()) { + if (uid == AID_ROOT) { + tag2uid.erase(ut); + update = true; + } else if (ut->second.find(uid) == ut->second.end()) { + const_cast(ut->second).emplace(uid); + update = true; + } + } else if (newOne && (uid != AID_ROOT)) { + tag2uid[tag].emplace(uid); + update = true; + } + + // updatePersist -> trigger output on modified + // content, reset tag2total if available + if (update && (itot != tag2total.end())) tag2total[tag] = 0; + } + + if (update) { + WritePersistEventLogTags(tag, uid, source); + } else if (warn && !newOne && source) { + // For the files, we want to report dupes. + android::prdebug("Multiple tag %" PRIu32 " %s %s %s", tag, + Name.c_str(), Format.c_str(), source); + } +} + +// Read the event log tags file, and build up our internal database +void LogTags::ReadFileEventLogTags(const char* filename, bool warn) { + bool etc = !strcmp(filename, system_event_log_tags); + bool debug = !etc && !strcmp(filename, debug_event_log_tags); + + if (!etc) { + RebuildFileEventLogTags(filename, warn); + } + std::string content; + if (android::base::ReadFileToString(filename, &content)) { + char* cp = (char*) content.c_str(); + char* endp = cp + content.length(); + + { + android::RWLock::AutoRLock writeLock(rwlock); + + file2watermark[filename] = content.length(); + } + + char* lineStart = cp; + while (cp < endp) { + if (*cp == '\n') { + lineStart = cp; + } else if (lineStart) { + if (*cp == '#') { + /* comment; just scan to end */ + lineStart = NULL; + } else if (isdigit(*cp)) { + unsigned long Tag = strtoul(cp, &cp, 10); + if (warn && (Tag > emptyTag)) { + android::prdebug("tag too large %lu", Tag); + } + while ((cp < endp) && (*cp != '\n') && isspace(*cp)) ++cp; + if (cp >= endp) break; + if (*cp == '\n') continue; + const char* name = cp; + /* Determine whether it is a valid tag name [a-zA-Z0-9_] */ + bool hasAlpha = false; + while ((cp < endp) && (isalnum(*cp) || (*cp == '_'))) { + if (!isdigit(*cp)) hasAlpha = true; + ++cp; + } + std::string Name(name, cp - name); +#ifdef ALLOW_NOISY_LOGGING_OF_PROBLEM_WITH_LOTS_OF_TECHNICAL_DEBT + static const size_t maximum_official_tag_name_size = 24; + if (warn && (Name.length() > maximum_official_tag_name_size)) { + android::prdebug("tag name too long %s", Name.c_str()); + } +#endif + if (hasAlpha && ((cp >= endp) || (*cp == '#') || isspace(*cp))) { + if (Tag > emptyTag) { + if (*cp != '\n') lineStart = NULL; + continue; + } + while ((cp < endp) && (*cp != '\n') && isspace(*cp)) ++cp; + const char* format = cp; + uid_t uid = AID_ROOT; + while ((cp < endp) && (*cp != '\n')) { + if (*cp == '#') { + uid = sniffUid(cp, endp); + lineStart = NULL; + break; + } + ++cp; + } + while ((cp > format) && isspace(cp[-1])) { + --cp; + lineStart = NULL; + } + std::string Format(format, cp - format); + + AddEventLogTags((uint32_t)Tag, uid, Name, Format, + filename, warn); + } else { + if (warn) { + android::prdebug("tag name invalid %.*s", + (int)(cp - name + 1), name); + } + lineStart = NULL; + } + } else if (!isspace(*cp)) break; + } + cp++; + } + } else if (warn) { + android::prdebug("Cannot read %s", filename); + } +} + +// Extract a 4-byte value from a byte stream. +static inline uint32_t get4LE(const char* msg) +{ + const uint8_t* src = reinterpret_cast(msg); + return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); +} + +// Additional persistent sources for invented log tags. Read the +// special pmsg event for log tags, and build up our internal +// database with any found. +void LogTags::ReadPersistEventLogTags() { + struct logger_list* logger_list = android_logger_list_alloc( + ANDROID_LOG_RDONLY | ANDROID_LOG_PSTORE | ANDROID_LOG_NONBLOCK, + 0, (pid_t)0); + if (!logger_list) return; + + struct logger* e = android_logger_open(logger_list, LOG_ID_EVENTS); + struct logger* s = android_logger_open(logger_list, LOG_ID_SECURITY); + if (!e && !s) { + android_logger_list_free(logger_list); + return; + } + + for (;;) { + struct log_msg log_msg; + int ret = android_logger_list_read(logger_list, &log_msg); + if (ret <= 0) break; + + const char* msg = log_msg.msg(); + if (!msg) continue; + if (log_msg.entry.len <= sizeof(uint32_t)) continue; + uint32_t Tag = get4LE(msg); + if (Tag != TAG_DEF_LOG_TAG) continue; + uid_t uid = (log_msg.entry.hdr_size >= sizeof(logger_entry_v4)) ? + log_msg.entry.uid : AID_ROOT; + + std::string Name; + std::string Format; + android_log_list_element elem; + { + android_log_event_list ctx(log_msg); + elem = ctx.read(); + if (elem.type != EVENT_TYPE_LIST) { + continue; + } + elem = ctx.read(); + if (elem.type != EVENT_TYPE_INT) { + continue; + } + Tag = elem.data.int32; + elem = ctx.read(); + if (elem.type != EVENT_TYPE_STRING) { + continue; + } + Name = std::string(elem.data.string, elem.len); + elem = ctx.read(); + if (elem.type != EVENT_TYPE_STRING) { + continue; + } + Format = std::string(elem.data.string, elem.len); + elem = ctx.read(); + } + if ((elem.type != EVENT_TYPE_LIST_STOP) || !elem.complete) continue; + + AddEventLogTags(Tag, uid, Name, Format); + } + android_logger_list_free(logger_list); +} + +LogTags::LogTags() { + ReadFileEventLogTags(system_event_log_tags); + // Following will likely fail on boot, but is required if logd restarts + ReadFileEventLogTags(dynamic_event_log_tags, false); + if (__android_log_is_debuggable()) { + ReadFileEventLogTags(debug_event_log_tags, false); + } + ReadPersistEventLogTags(); + + logtags = this; +} + +// Converts an event tag into a name +const char* LogTags::tagToName(uint32_t tag) const { + tag2name_const_iterator it; + + android::RWLock::AutoRLock readLock(const_cast(rwlock)); + + it = tag2name.find(tag); + if ((it == tag2name.end()) || (it->second.length() == 0)) return NULL; + + return it->second.c_str(); +} + +// Prototype in LogUtils.h allowing external access to our database. +// +// This must be a pure reader to our database, as everything else is +// guaranteed single-threaded except this access point which is +// asynchonous and can be multithreaded and thus rentrant. The +// object's rwlock is only used to guarantee atomic access to the +// unordered_map to prevent corruption, with a requirement to be a +// low chance of contention for this call. If we end up changing +// this algorithm resulting in write, then we should use a different +// lock than the object's rwlock to protect groups of associated +// actions. +const char* android::tagToName(uint32_t tag) { + LogTags* me = logtags; + + if (!me) return NULL; + me->WritePmsgEventLogTags(tag); + return me->tagToName(tag); +} + +// Prototype in LogUtils.h allowing external access to our database. +// +// This only works on userdebug and eng devices to re-read the +// /data/misc/logd/event-log-tags file right after /data is mounted. +// The operation is near to boot and should only happen once. There +// are races associated with its use since it can trigger a Rebuild +// of the file, but that is a can-not-happen since the file was not +// read yet. More dangerous if called later, but if all is well it +// should just skip over everything and not write any new entries. +void android::ReReadEventLogTags() { + LogTags* me = logtags; + + if (me && __android_log_is_debuggable()) { + me->ReadFileEventLogTags(me->debug_event_log_tags); + } +} + +// converts an event tag into a format +const char* LogTags::tagToFormat(uint32_t tag) const { + tag2format_const_iterator iform; + + android::RWLock::AutoRLock readLock(const_cast(rwlock)); + + iform = tag2format.find(tag); + if (iform == tag2format.end()) return NULL; + + return iform->second.c_str(); +} + +// converts a name into an event tag +uint32_t LogTags::nameToTag(const char* name) const { + uint32_t ret = emptyTag; + + // Bug: Only works for a single entry, we can have multiple entries, + // one for each format, so we find first entry recorded, or entry with + // no format associated with it. + + android::RWLock::AutoRLock readLock(const_cast(rwlock)); + + key2tag_const_iterator ik = key2tag.find(std::string(name)); + if (ik != key2tag.end()) ret = ik->second; + + return ret; +} + +// Caller must perform locks, can be under reader (for pre-check) or +// writer lock. We use this call to invent a new deterministically +// random tag, unique is cleared if no conflicts. If format is NULL, +// we are in readonly mode. +uint32_t LogTags::nameToTag_locked(const std::string& name, + const char* format, + bool& unique) { + key2tag_const_iterator ik; + + bool write = format != NULL; + unique = write; + + if (!write) { + // Bug: Only works for a single entry, we can have multiple entries, + // one for each format, so we find first entry recorded, or entry with + // no format associated with it. + ik = key2tag.find(name); + if (ik == key2tag.end()) return emptyTag; + return ik->second; + } + + std::string Key(name); + if (*format) Key += std::string("+") + format; + + ik = key2tag.find(Key); + if (ik != key2tag.end()) { + unique = false; + return ik->second; + } + + size_t Hash = key2tag.hash_function()(Key); + uint32_t Tag = Hash; + // This sets an upper limit on the conflics we are allowed to deal with. + for (unsigned i = 0; i < 256; ) { + tag2name_const_iterator it = tag2name.find(Tag); + if (it == tag2name.end()) return Tag; + std::string localKey(it->second); + tag2format_const_iterator iform = tag2format.find(Tag); + if ((iform == tag2format.end()) && iform->second.length()) { + localKey += "+" + iform->second; + } + unique = !!it->second.compare(localKey); + if (!unique) return Tag; // unlikely except in a race + + ++i; + // Algorithm to convert hash to next tag + if (i < 32) { + Tag = (Hash >> i); + // size_t is 32 bits, or upper word zero, rotate + if ((sizeof(Hash) <= 4) || + ((Hash & (uint64_t(-1LL) << 32)) == 0)) { + Tag |= Hash << (32 - i); + } + } else { + Tag = Hash + i - 31; + } + } + return emptyTag; +} + +static int openFile(const char* name, int mode, bool warning) { + int fd = TEMP_FAILURE_RETRY(open(name, mode)); + if ((fd < 0) && warning) { + android::prdebug("Failed open %s (%d)", name, errno); + } + return fd; +} + +void LogTags::WritePmsgEventLogTags(uint32_t tag, uid_t uid) { + android::RWLock::AutoRLock readLock(rwlock); + + tag2total_const_iterator itot = tag2total.find(tag); + if (itot == tag2total.end()) return; // source is a static entry + + size_t lastTotal = itot->second; + + // Every 16K (half the smallest configurable pmsg buffer size) record + static const size_t rate_to_pmsg = 16 * 1024; + if (lastTotal && ((android::sizesTotal() - lastTotal) < rate_to_pmsg)) { + return; + } + + static int pmsg_fd = -1; + if (pmsg_fd < 0) { + pmsg_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY | O_CLOEXEC)); + // unlikely, but deal with partners with borken pmsg + if (pmsg_fd < 0) return; + } + + std::string Name = tag2name[tag]; + tag2format_const_iterator iform = tag2format.find(tag); + std::string Format = (iform != tag2format.end()) ? iform->second : ""; + + __android_log_event_list ctx(TAG_DEF_LOG_TAG); + ctx << tag << Name << Format; + std::string buffer(ctx); + if (buffer.length() <= 0) return; // unlikely + + /* + * struct { + * // what we provide to pstore + * android_pmsg_log_header_t pmsgHeader; + * // what we provide to file + * android_log_header_t header; + * // caller provides + * union { + * struct { + * char prio; + * char payload[]; + * } string; + * struct { + * uint32_t tag + * char payload[]; + * } binary; + * }; + * }; + */ + + struct timespec ts; + clock_gettime(android_log_clockid(), &ts); + + android_log_header_t header = { + .id = LOG_ID_EVENTS, + .tid = (uint16_t)gettid(), + .realtime.tv_sec = (uint32_t)ts.tv_sec, + .realtime.tv_nsec = (uint32_t)ts.tv_nsec, + }; + + uint32_t outTag = TAG_DEF_LOG_TAG; + outTag = get4LE((const char*)&outTag); + + android_pmsg_log_header_t pmsgHeader = { + .magic = LOGGER_MAGIC, + .len = (uint16_t)(sizeof(pmsgHeader) + sizeof(header) + + sizeof(outTag) + buffer.length()), + .uid = (uint16_t)AID_ROOT, + .pid = (uint16_t)getpid(), + }; + + struct iovec Vec[] = { + { (unsigned char*)&pmsgHeader, sizeof(pmsgHeader) }, + { (unsigned char*)&header, sizeof(header) }, + { (unsigned char*)&outTag, sizeof(outTag) }, + { (unsigned char*)const_cast(buffer.data()), buffer.length() } + }; + + tag2uid_const_iterator ut = tag2uid.find(tag); + if (ut == tag2uid.end()) { + TEMP_FAILURE_RETRY(writev(pmsg_fd, Vec, arraysize(Vec))); + } else if (uid != AID_ROOT) { + pmsgHeader.uid = (uint16_t)uid; + TEMP_FAILURE_RETRY(writev(pmsg_fd, Vec, arraysize(Vec))); + } else { + for (auto &it : ut->second) { + pmsgHeader.uid = (uint16_t)it; + TEMP_FAILURE_RETRY(writev(pmsg_fd, Vec, arraysize(Vec))); + } + } +} + +void LogTags::WriteDynamicEventLogTags(uint32_t tag, uid_t uid) { + static const int mode = O_WRONLY | O_APPEND | + O_CLOEXEC | O_NOFOLLOW | O_BINARY; + + int fd = openFile(dynamic_event_log_tags, mode, true); + if (fd < 0) return; + + android::RWLock::AutoWLock writeLock(rwlock); + + std::string ret = formatEntry_locked(tag, uid, false); + android::base::WriteStringToFd(ret, fd); + TEMP_FAILURE_RETRY(close(fd)); + + size_t size = 0; + file2watermark_const_iterator iwater; + + iwater = file2watermark.find(dynamic_event_log_tags); + if (iwater != file2watermark.end()) size = iwater->second; + + file2watermark[dynamic_event_log_tags] = size + ret.length(); +} + +void LogTags::WriteDebugEventLogTags(uint32_t tag, uid_t uid) { + static const int mode = O_WRONLY | O_APPEND | + O_CLOEXEC | O_NOFOLLOW | O_BINARY; + + static bool one = true; + int fd = openFile(debug_event_log_tags, mode, one); + one = fd >= 0; + if (!one) return; + + android::RWLock::AutoWLock writeLock(rwlock); + + std::string ret = formatEntry_locked(tag, uid, false); + android::base::WriteStringToFd(ret, fd); + TEMP_FAILURE_RETRY(close(fd)); + + size_t size = 0; + file2watermark_const_iterator iwater; + + iwater = file2watermark.find(debug_event_log_tags); + if (iwater != file2watermark.end()) size = iwater->second; + + file2watermark[debug_event_log_tags] = size + ret.length(); +} + +// How we maintain some runtime or reboot stickiness +void LogTags::WritePersistEventLogTags(uint32_t tag, + uid_t uid, const char* source) { + // very unlikely + bool etc = source && !strcmp(source, system_event_log_tags); + if (etc) return; + + bool dynamic = source && !strcmp(source, dynamic_event_log_tags); + bool debug = (!dynamic && + source && + !strcmp(source, debug_event_log_tags)) || + !__android_log_is_debuggable(); + + WritePmsgEventLogTags(tag, uid); + + size_t lastTotal = 0; + { + android::RWLock::AutoRLock readLock(rwlock); + + tag2total_const_iterator itot = tag2total.find(tag); + if (itot != tag2total.end()) lastTotal = itot->second; + } + + if (lastTotal == 0) { // denotes first time for this one + if (!dynamic || !RebuildFileEventLogTags(dynamic_event_log_tags)) { + WriteDynamicEventLogTags(tag, uid); + } + + if (!debug && !RebuildFileEventLogTags(debug_event_log_tags)) { + WriteDebugEventLogTags(tag, uid); + } + } + + lastTotal = android::sizesTotal(); + if (!lastTotal) ++lastTotal; + + // record totals for next watermark. + android::RWLock::AutoWLock writeLock(rwlock); + tag2total[tag] = lastTotal; +} + +// nameToTag converts a name into an event tag. If format is NULL, then we +// are in readonly mode. +uint32_t LogTags::nameToTag(uid_t uid, const char* name, const char* format) { + std::string Name = std::string(name); + bool write = format != NULL; + bool updateUid = uid != AID_ROOT; + bool updateFormat = format && *format; + bool unique; + uint32_t Tag; + + { + android::RWLock::AutoRLock readLock(rwlock); + + Tag = nameToTag_locked(Name, format, unique); + if (updateUid && (Tag != emptyTag) && !unique) { + tag2uid_const_iterator ut = tag2uid.find(Tag); + if (updateUid) { + if ((ut != tag2uid.end()) && + (ut->second.find(uid) == ut->second.end())) { + unique = write; // write passthrough to update uid counts + if (!write) Tag = emptyTag; // deny read access + } + } else { + unique = write && (ut != tag2uid.end()); + } + } + } + + if (Tag == emptyTag) return Tag; + WritePmsgEventLogTags(Tag, uid); // record references periodically + if (!unique) return Tag; + + bool updateWrite = false; + bool updateTag; + + // Special case of AddEventLogTags, checks per-uid counter which makes + // no sense there, and is also optimized somewhat to reduce write times. + { + android::RWLock::AutoWLock writeLock(rwlock); + + // double check after switch from read lock to write lock for Tag + updateTag = tag2name.find(Tag) == tag2name.end(); + // unlikely, either update, race inviting conflict or multiple uids + if (!updateTag) { + Tag = nameToTag_locked(Name, format, unique); + if (Tag == emptyTag) return Tag; + // is it multiple uid's setting this value + if (!unique) { + tag2uid_const_iterator ut = tag2uid.find(Tag); + if (updateUid) { + // Add it to the uid list + if ((ut == tag2uid.end()) || + (ut->second.find(uid) != ut->second.end())) return Tag; + const_cast(ut->second).emplace(uid); + updateWrite = true; + } else { + if (ut == tag2uid.end()) return Tag; + // (system) adding a global one, erase the uid list + tag2uid.erase(ut); + updateWrite = true; + } + } + } + + // Update section + size_t count; + if (updateUid) { + count = 0; + uid2count_const_iterator ci = uid2count.find(uid); + if (ci != uid2count.end()) { + count = ci->second; + if (count >= max_per_uid) { + if (!updateWrite) return emptyTag; + // If we are added to the per-Uid perms, leak the Tag + // if it already exists. + updateUid = false; + updateTag = false; + updateFormat = false; + } + } + } + + // updateWrite -> trigger output on modified content, reset tag2total + // also sets static to dynamic entries if they are alterred, + // only occurs if they have a uid, and runtime adds another uid. + if (updateWrite) tag2total[Tag] = 0; + + if (updateTag) { + // mark as a dynamic entry, but do not upset current total counter + tag2total_const_iterator itot = tag2total.find(Tag); + if (itot == tag2total.end()) tag2total[Tag] = 0; + + if (*format) { + key2tag[Name + "+" + format] = Tag; + if (key2tag.find(Name) == key2tag.end()) key2tag[Name] = Tag; + } else { + key2tag[Name] = Tag; + } + tag2name[Tag] = Name; + } + if (updateFormat) tag2format[Tag] = format; + + if (updateUid) { + tag2uid[Tag].emplace(uid); + uid2count[uid] = count + 1; + } + } + + if (updateTag || updateFormat || updateWrite) { + WritePersistEventLogTags(Tag, uid); + } + + return Tag; +} + +std::string LogTags::formatEntry(uint32_t tag, uid_t uid, + const char* name, + const char* format) { + if (!format || !format[0]) { + return android::base::StringPrintf("%" PRIu32 "\t%s\n", tag, name); + } + size_t len = (strlen(name) + 7) / 8; + static const char tabs[] = "\t\t\t"; + if (len > strlen(tabs)) len = strlen(tabs); + std::string Uid; + if (uid != AID_ROOT) Uid = android::base::StringPrintf(" # uid=%u", uid); + return android::base::StringPrintf("%" PRIu32 "\t%s%s\t%s%s\n", + tag, name, &tabs[len], format, + Uid.c_str()); +} + +std::string LogTags::formatEntry_locked(uint32_t tag, uid_t uid, + bool authenticate) { + const char* name = tag2name[tag].c_str(); + + const char* format = ""; + tag2format_const_iterator iform = tag2format.find(tag); + if (iform != tag2format.end()) format = iform->second.c_str(); + + // Access permission test, do not report dynamic entries + // that do not belong to us. + tag2uid_const_iterator ut = tag2uid.find(tag); + if (ut == tag2uid.end()) { + return formatEntry(tag, AID_ROOT, name, format); + } + if (uid != AID_ROOT) { + if (authenticate && (ut->second.find(uid) == ut->second.end())) { + return std::string(""); + } + return formatEntry(tag, uid, name, format); + } + + // Show all, one for each registered uid (we are group root) + std::string ret; + for (auto &it : ut->second) { + ret += formatEntry(tag, it, name, format); + } + return ret; +} + +std::string LogTags::formatGetEventTag(uid_t uid, + const char* name, const char* format) { + bool all = name && (name[0] == '*') && !name[1]; + bool list = !name || all; + std::string ret; + + if (!list) { + // switch to read entry only if format == "*" + if (format && (format[0] == '*') && !format[1]) format = NULL; + + // WAI: for null format, only works for a single entry, we can have + // multiple entries, one for each format, so we find first entry + // recorded, or entry with no format associated with it. + // We may desire to print all that match the name, but we did not + // add a mapping table for that and the cost is too high. + uint32_t tag = nameToTag(uid, name, format); + if (tag == emptyTag) return std::string("-1 ESRCH"); + if (uid == AID_ROOT) { + android::RWLock::AutoRLock readLock(rwlock); + + // first uid in list so as to manufacture an accurate reference + tag2uid_const_iterator ut = tag2uid.find(tag); + if ((ut != tag2uid.end()) && + (ut->second.begin() != ut->second.end())) { + uid = *(ut->second.begin()); + } + } + ret = formatEntry(tag, uid, name, format ?: tagToFormat(tag)); + if (!ret.length()) return std::string("-1 ESRCH"); + return ret; + } + + android::RWLock::AutoRLock readLock(rwlock); + if (all) { + // everything under the sun + for (const auto& it : tag2name) { + ret += formatEntry_locked(it.first, uid); + } + } else { + // set entries are dynamic + for (const auto& it : tag2total) { + ret += formatEntry_locked(it.first, uid); + } + } + return ret; +} diff --git a/logd/LogTags.h b/logd/LogTags.h new file mode 100644 index 000000000..37a6d9632 --- /dev/null +++ b/logd/LogTags.h @@ -0,0 +1,118 @@ +/* + * Copyright (C) 2017 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_TAGS_H__ +#define _LOGD_LOG_TAGS_H__ + +#include +#include +#include + +#include + +class LogTags { + // This lock protects all the unordered_map accesses below. It + // is a reader/writer lock so that contentions are kept to a + // minimum since writes are rare, even administratably when + // reads are extended. Resist the temptation to use the writer + // lock to protect anything outside the following unordered_maps + // as that would increase the reader contentions. Use a separate + // mutex to protect the other entities. + android::RWLock rwlock; + + // key is Name + "+" + Format + std::unordered_map key2tag; + typedef std::unordered_map::const_iterator key2tag_const_iterator; + + // Allows us to manage access permissions based on uid registrants + // Global entries are specifically erased. + typedef std::unordered_set uid_list; + std::unordered_map tag2uid; + typedef std::unordered_map::const_iterator tag2uid_const_iterator; + + std::unordered_map tag2name; + typedef std::unordered_map::const_iterator tag2name_const_iterator; + + std::unordered_map tag2format; + typedef std::unordered_map::const_iterator tag2format_const_iterator; + + static const size_t max_per_uid = 256; // Put a cap on the tags per uid + std::unordered_map uid2count; + typedef std::unordered_map::const_iterator uid2count_const_iterator; + + // Dynamic entries are assigned + std::unordered_map tag2total; + typedef std::unordered_map::const_iterator tag2total_const_iterator; + + // emplace unique tag + uint32_t nameToTag(uid_t uid, const char* name, const char* format); + // find unique or associated tag + uint32_t nameToTag_locked(const std::string& name, const char* format, bool &unique); + + // Record expected file watermarks to detect corruption. + std::unordered_map file2watermark; + typedef std::unordered_map::const_iterator file2watermark_const_iterator; + + void ReadPersistEventLogTags(); + + // format helpers + // format a single entry, does not need object data + static std::string formatEntry(uint32_t tag, uid_t uid, + const char* name, const char* format); + // caller locks, database lookup, authenticate against uid + std::string formatEntry_locked(uint32_t tag, uid_t uid, + bool authenticate = true); + + bool RebuildFileEventLogTags(const char* filename, bool warn = true); + + void AddEventLogTags(uint32_t tag, uid_t uid, + const std::string& Name, const std::string& Format, + const char* source = NULL, bool warn = false); + + void WriteDynamicEventLogTags(uint32_t tag, uid_t uid); + void WriteDebugEventLogTags(uint32_t tag, uid_t uid); + // push tag details to persistent storage + void WritePersistEventLogTags(uint32_t tag, + uid_t uid = AID_ROOT, + const char* source = NULL); + + static const uint32_t emptyTag = uint32_t(-1); + +public: + + static const char system_event_log_tags[]; + static const char dynamic_event_log_tags[]; + // Only for userdebug and eng + static const char debug_event_log_tags[]; + + LogTags(); + + void WritePmsgEventLogTags(uint32_t tag, uid_t uid = AID_ROOT); + void ReadFileEventLogTags(const char* filename, bool warn = true); + + // reverse lookup from tag + const char* tagToName(uint32_t tag) const; + const char* tagToFormat(uint32_t tag) const; + // find associated tag + uint32_t nameToTag(const char* name) const; + + // emplace tag if necessary, provide event-log-tag formated output in string + std::string formatGetEventTag(uid_t uid, + const char* name, + const char* format); +}; + +#endif // _LOGD_LOG_TAGS_H__ diff --git a/logd/LogUtils.h b/logd/LogUtils.h index 70f24e4d9..f044b2744 100644 --- a/logd/LogUtils.h +++ b/logd/LogUtils.h @@ -39,8 +39,9 @@ size_t sizesTotal(); char *pidToName(pid_t pid); char *tidToName(pid_t tid); -// Furnished in main.cpp. Thread safe. -const char *tagToName(size_t *len, uint32_t tag); +// Furnished in LogTags.cpp. Thread safe. +const char *tagToName(uint32_t tag); +void ReReadEventLogTags(); // Furnished by LogKlog.cpp. const char* strnstr(const char* s, size_t len, const char* needle); diff --git a/logd/event.logtags b/logd/event.logtags index 0d24df0cb..39063a982 100644 --- a/logd/event.logtags +++ b/logd/event.logtags @@ -35,3 +35,4 @@ 1003 auditd (avc|3) 1004 chatty (dropped|3) +1005 tag_def (tag|1),(name|3),(format|3) diff --git a/logd/logd.rc b/logd/logd.rc index 54349dd67..ee89b83b5 100644 --- a/logd/logd.rc +++ b/logd/logd.rc @@ -14,3 +14,10 @@ service logd-reinit /system/bin/logd --reinit user logd group logd writepid /dev/cpuset/system-background/tasks + +on fs + write /dev/event-log-tags "# content owned by logd +" + chown logd logd /dev/event-log-tags + chmod 0644 /dev/event-log-tags + restorecon /dev/event-log-tags diff --git a/logd/logtagd.rc b/logd/logtagd.rc new file mode 100644 index 000000000..46aa8c1d9 --- /dev/null +++ b/logd/logtagd.rc @@ -0,0 +1,9 @@ +# +# logtagd event log tag service (debug only) +# +on post-fs-data + mkdir /data/misc/logd 0700 logd log + write /data/misc/logd/event-log-tags "" + chown logd log /data/misc/logd/event-log-tags + chmod 0600 /data/misc/logd/event-log-tags + restorecon /data/misc/logd/event-log-tags diff --git a/logd/main.cpp b/logd/main.cpp index 5878f151e..2551f2e9b 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -244,7 +244,7 @@ static void *reinit_thread_start(void * /*obj*/) { // anything else, we have even lesser privileges and accept our fate. Not // worth checking for error returns setting this thread's privileges. (void)setgid(AID_SYSTEM); // readonly access to /data/system/packages.list - (void)setuid(AID_LOGD); // access to everything logd. + (void)setuid(AID_LOGD); // access to everything logd, eg /data/misc/logd while (reinit_running && !sem_wait(&reinit) && reinit_running) { @@ -271,6 +271,7 @@ static void *reinit_thread_start(void * /*obj*/) { logBuf->init(); logBuf->initPrune(NULL); } + android::ReReadEventLogTags(); } return NULL; @@ -304,24 +305,6 @@ void reinit_signal_handler(int /*signal*/) { sem_post(&reinit); } -// tagToName converts an events tag into a name -const char *android::tagToName(size_t *len, uint32_t tag) { - static const EventTagMap *map; - - if (!map) { - sem_wait(&sem_name); - if (!map) { - map = android_openEventTagMap(NULL); - } - sem_post(&sem_name); - if (!map) { - if (len) len = 0; - return NULL; - } - } - return android_lookupEventTag_len(map, len, tag); -} - static void readDmesg(LogAudit *al, LogKlog *kl) { if (!al && !kl) { return; diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index 2a6cdc8f5..0db33b755 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -39,12 +39,8 @@ #include "../libaudit.h" // pickup AUDIT_RATE_LIMIT_* #include "../LogReader.h" // pickup LOGD_SNDTIMEO -/* - * returns statistics - */ -static void my_android_logger_get_statistics(char *buf, size_t len) +static void send_to_control(char* buf, size_t len) { - snprintf(buf, len, "getStatistics 0 1 2 3 4"); int sock = socket_local_client("logd", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_STREAM); @@ -74,6 +70,15 @@ static void my_android_logger_get_statistics(char *buf, size_t len) } } +/* + * returns statistics + */ +static void my_android_logger_get_statistics(char *buf, size_t len) +{ + snprintf(buf, len, "getStatistics 0 1 2 3 4"); + send_to_control(buf, len); +} + static void alloc_statistics(char **buffer, size_t *length) { size_t len = 8192; @@ -816,6 +821,44 @@ TEST(logd, SNDTIMEO) { close(fd); } +TEST(logd, getEventTag_list) { +#ifdef __ANDROID__ + char buffer[256]; + memset(buffer, 0, sizeof(buffer)); + snprintf(buffer, sizeof(buffer), "getEventTag name=*"); + send_to_control(buffer, sizeof(buffer)); + buffer[sizeof(buffer) - 1] = '\0'; + char *cp; + long ret = strtol(buffer, &cp, 10); + EXPECT_GT(ret, 4096); +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + +TEST(logd, getEventTag_newentry) { +#ifdef __ANDROID__ + char buffer[256]; + memset(buffer, 0, sizeof(buffer)); + log_time now(CLOCK_MONOTONIC); + char name[64]; + snprintf(name, sizeof(name), "a%" PRIu64, now.nsec()); + snprintf(buffer, sizeof(buffer), + "getEventTag name=%s format=\"(new|1)\"", name); + send_to_control(buffer, sizeof(buffer)); + buffer[sizeof(buffer) - 1] = '\0'; + char *cp; + long ret = strtol(buffer, &cp, 10); + EXPECT_GT(ret, 16); + EXPECT_TRUE(strstr(buffer, "\t(new|1)") != NULL); + EXPECT_TRUE(strstr(buffer, name) != NULL); + // ToDo: also look for this in /data/misc/logd/event-log-tags and + // /dev/event-log-tags. +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} + static inline int32_t get4LE(const char* src) { return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);