diff --git a/liblog/event_tag_map.cpp b/liblog/event_tag_map.cpp index fec5deee3..1f08eb4d6 100644 --- a/liblog/event_tag_map.cpp +++ b/liblog/event_tag_map.cpp @@ -19,6 +19,7 @@ #include #include #include +#include #include #include #include @@ -26,15 +27,63 @@ #include #include +#include #include #include +#include +#include +#include #include "log_portability.h" +#include "logd_reader.h" #define OUT_TAG "EventTagMap" -typedef std::experimental::string_view MapString; +class MapString { +private: + const std::string* alloc; // HAS-AN + const std::experimental::string_view str; // HAS-A + +public: + operator const std::experimental::string_view() const { return str; } + + const char* data() const { return str.data(); } + size_t length() const { return str.length(); } + + bool operator== (const MapString& rval) const { + if (length() != rval.length()) return false; + if (length() == 0) return true; + return fastcmp(data(), rval.data(), length()) == 0; + } + bool operator!= (const MapString& rval) const { + return !(*this == rval); + } + + MapString(const char* str, size_t len) : alloc(NULL), str(str, len) { } + explicit MapString(const std::string& str) : + alloc(new std::string(str)), + str(alloc->data(), alloc->length()) { } + MapString(MapString &&rval) : + alloc(rval.alloc), + str(rval.data(), rval.length()) { + rval.alloc = NULL; + } + explicit MapString(const MapString &rval) : + alloc(rval.alloc ? new std::string(*rval.alloc) : NULL), + str(alloc ? alloc->data() : rval.data(), rval.length()) { } + + ~MapString() { if (alloc) delete alloc; } +}; + +// Hash for MapString +template <> struct std::hash + : public std::unary_function { + size_t operator()(const MapString& __t) const noexcept { + if (!__t.length()) return 0; + return std::hash()(std::experimental::string_view(__t)); + } +}; typedef std::pair TagFmt; @@ -60,6 +109,10 @@ struct EventTagMap { private: std::unordered_map Idx2TagFmt; + std::unordered_map TagFmt2Idx; + std::unordered_map Tag2Idx; + // protect unordered sets + android::RWLock rwlock; public: EventTagMap() { @@ -69,6 +122,8 @@ public: ~EventTagMap() { Idx2TagFmt.clear(); + TagFmt2Idx.clear(); + Tag2Idx.clear(); for (size_t which = 0; which < NUM_MAPS; ++which) { if (mapAddr[which]) { munmap(mapAddr[which], mapLen[which]); @@ -79,37 +134,93 @@ public: bool emplaceUnique(uint32_t tag, const TagFmt& tagfmt, bool verbose = false); const TagFmt* find(uint32_t tag) const; + int find(TagFmt&& tagfmt) const; + int find(MapString&& tag) const; }; bool EventTagMap::emplaceUnique(uint32_t tag, const TagFmt& tagfmt, bool verbose) { - std::unordered_map::const_iterator it; - it = Idx2TagFmt.find(tag); - if (it != Idx2TagFmt.end()) { - if (verbose) { - fprintf(stderr, - OUT_TAG ": duplicate tag entries %" PRIu32 - ":%.*s:%.*s and %" PRIu32 ":%.*s:%.*s)\n", - it->first, - (int)it->second.first.length(), it->second.first.data(), - (int)it->second.second.length(), it->second.second.data(), - tag, - (int)tagfmt.first.length(), tagfmt.first.data(), - (int)tagfmt.second.length(), tagfmt.second.data()); + bool ret = true; + static const char errorFormat[] = OUT_TAG ": duplicate tag entries %" PRIu32 + ":%.*s:%.*s and %" PRIu32 + ":%.*s:%.*s)\n"; + android::RWLock::AutoWLock writeLock(rwlock); + { + std::unordered_map::const_iterator it; + it = Idx2TagFmt.find(tag); + if (it != Idx2TagFmt.end()) { + if (verbose) { + fprintf(stderr, errorFormat, + it->first, + (int)it->second.first.length(), it->second.first.data(), + (int)it->second.second.length(), it->second.second.data(), + tag, + (int)tagfmt.first.length(), tagfmt.first.data(), + (int)tagfmt.second.length(), tagfmt.second.data()); + } + ret = false; + } else { + Idx2TagFmt.emplace(std::make_pair(tag, tagfmt)); } - return false; } - Idx2TagFmt.emplace(std::make_pair(tag, tagfmt)); - return true; + { + std::unordered_map::const_iterator it; + it = TagFmt2Idx.find(tagfmt); + if (it != TagFmt2Idx.end()) { + if (verbose) { + fprintf(stderr, errorFormat, + it->second, + (int)it->first.first.length(), it->first.first.data(), + (int)it->first.second.length(), it->first.second.data(), + tag, + (int)tagfmt.first.length(), tagfmt.first.data(), + (int)tagfmt.second.length(), tagfmt.second.data()); + } + ret = false; + } else { + TagFmt2Idx.emplace(std::make_pair(tagfmt, tag)); + } + } + + { + std::unordered_map::const_iterator it; + it = Tag2Idx.find(tagfmt.first); + if (!tagfmt.second.length() && (it != Tag2Idx.end())) { + Tag2Idx.erase(it); + it = Tag2Idx.end(); + } + if (it == Tag2Idx.end()) { + Tag2Idx.emplace(std::make_pair(tagfmt.first, tag)); + } + } + + return ret; } const TagFmt* EventTagMap::find(uint32_t tag) const { std::unordered_map::const_iterator it; + android::RWLock::AutoRLock readLock(const_cast(rwlock)); it = Idx2TagFmt.find(tag); if (it == Idx2TagFmt.end()) return NULL; return &(it->second); } +int EventTagMap::find(TagFmt&& tagfmt) const { + std::unordered_map::const_iterator it; + android::RWLock::AutoRLock readLock(const_cast(rwlock)); + it = TagFmt2Idx.find(std::move(tagfmt)); + if (it == TagFmt2Idx.end()) return -1; + return it->second; +} + +int EventTagMap::find(MapString&& tag) const { + std::unordered_map::const_iterator it; + android::RWLock::AutoRLock readLock(const_cast(rwlock)); + it = Tag2Idx.find(std::move(tag)); + if (it == Tag2Idx.end()) return -1; + return it->second; +} + // Scan one tag line. // // "*pData" should be pointing to the first digit in the tag number. On @@ -380,3 +491,75 @@ LIBLOG_ABI_PUBLIC const char* android_lookupEventTag(const EventTagMap* map, if (*cp) *cp = '\0'; // Trigger copy on write :-( and why deprecated. return tagStr; } + +// Look up tagname, generate one if necessary, and return a tag +LIBLOG_ABI_PUBLIC int android_lookupEventTagNum(EventTagMap* map, + const char* tagname, + const char* format, + int prio) { + size_t len = strlen(tagname); + if (!len) { + errno = EINVAL; + return -1; + } + + if ((prio != ANDROID_LOG_UNKNOWN) && (prio < ANDROID_LOG_SILENT) && + !__android_log_is_loggable_len(prio, tagname, len, + __android_log_is_debuggable() ? + ANDROID_LOG_VERBOSE : + ANDROID_LOG_DEBUG)) { + errno = EPERM; + return -1; + } + + if (!format) format=""; + ssize_t fmtLen = strlen(format); + int ret = map->find(TagFmt(std::make_pair(MapString(tagname, len), + MapString(format, fmtLen)))); + if (ret != -1) return ret; + + // call event tag service to arrange for a new tag + char *buf = NULL; + // Can not use android::base::StringPrintf, asprintf + free instead. + static const char command_template[] = "getEventTag name=%s format=\"%s\""; + ret = asprintf(&buf, command_template, tagname, format); + if (ret > 0) { + // Add some buffer margin for an estimate of the full return content. + char *cp; + size_t size = ret - strlen(command_template) + + strlen("65535\n4294967295\t?\t\t\t?\t# uid=32767\n\n\f?success?"); + if (size > (size_t)ret) { + cp = static_cast(realloc(buf, size)); + if (cp) { + buf = cp; + } else { + size = ret; + } + } else { + size = ret; + } + // Ask event log tag service for an allocation + if (__send_log_msg(buf, size) >= 0) { + buf[size - 1] = '\0'; + unsigned long val = strtoul(buf, &cp, 10); // return size + if ((buf != cp) && (val > 0) && (*cp == '\n')) { // truncation OK + val = strtoul(cp + 1, &cp, 10); // allocated tag number + if ((val > 0) && (val < UINT32_MAX) && (*cp == '\t')) { + free(buf); + ret = val; + // cache + map->emplaceUnique(ret, TagFmt(std::make_pair( + MapString(std::string(tagname, len)), + MapString(std::string(format, fmtLen))))); + return ret; + } + } + } + free(buf); + } + + // Hail Mary + ret = map->find(MapString(tagname, len)); + if (ret == -1) errno = ESRCH; + return ret; +} diff --git a/liblog/fake_log_device.c b/liblog/fake_log_device.c index 493922101..957129ed9 100644 --- a/liblog/fake_log_device.c +++ b/liblog/fake_log_device.c @@ -715,6 +715,12 @@ LIBLOG_HIDDEN ssize_t fakeLogWritev(int fd, return redirectWritev(fd, vector, count); } +LIBLOG_HIDDEN ssize_t __send_log_msg(char *buf __unused, + size_t buf_size __unused) +{ + return -ENODEV; +} + LIBLOG_ABI_PUBLIC int __android_log_is_loggable(int prio, const char *tag __unused, int def) diff --git a/liblog/include/log/event_tag_map.h b/liblog/include/log/event_tag_map.h index 22e62ec98..e57e47bb2 100644 --- a/liblog/include/log/event_tag_map.h +++ b/liblog/include/log/event_tag_map.h @@ -58,6 +58,12 @@ const char* android_lookupEventTag_len(const EventTagMap* map, const char* android_lookupEventFormat_len(const EventTagMap* map, size_t* len, unsigned int tag); +/* + * Look up tagname, generate one if necessary, and return a tag + */ +int android_lookupEventTagNum(EventTagMap* map, const char* tagname, + const char* format, int prio); + #ifdef __cplusplus } #endif diff --git a/liblog/logd_reader.c b/liblog/logd_reader.c index 99d7fea3b..ccc7da8ae 100644 --- a/liblog/logd_reader.c +++ b/liblog/logd_reader.c @@ -37,6 +37,7 @@ #include "config_read.h" #include "log_portability.h" +#include "logd_reader.h" #include "logger.h" /* branchless on many architectures. */ @@ -324,6 +325,11 @@ done: return ret; } +LIBLOG_HIDDEN ssize_t __send_log_msg(char *buf, size_t buf_size) +{ + return send_log_msg(NULL, NULL, buf, buf_size); +} + static int check_log_success(char *buf, ssize_t ret) { if (ret < 0) { diff --git a/liblog/logd_reader.h b/liblog/logd_reader.h new file mode 100644 index 000000000..04c2cf2b0 --- /dev/null +++ b/liblog/logd_reader.h @@ -0,0 +1,30 @@ +/* + * Copyright (C) 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. + */ + +#ifndef _LIBLOG_LOGD_READER_H__ +#define _LIBLOG_LOGD_READER_H__ + +#include + +#include "log_portability.h" + +__BEGIN_DECLS + +LIBLOG_HIDDEN ssize_t __send_log_msg(char *buf, size_t buf_size); + +__END_DECLS + +#endif /* _LIBLOG_LOGD_READER_H__ */ diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp index 5420f684d..dc411c326 100644 --- a/liblog/tests/liblog_benchmark.cpp +++ b/liblog/tests/liblog_benchmark.cpp @@ -15,6 +15,8 @@ */ #include +#include +#include #include #include #include @@ -22,6 +24,7 @@ #include +#include #include #include #include @@ -695,7 +698,7 @@ BENCHMARK(BM_security); // Keep maps around for multiple iterations static std::unordered_set set; -static const EventTagMap* map; +static EventTagMap* map; static bool prechargeEventMap() { if (map) return true; @@ -785,3 +788,142 @@ static void BM_lookupEventFormat(int iters) { StopBenchmarkTiming(); } BENCHMARK(BM_lookupEventFormat); + +/* + * Measure the time it takes for android_lookupEventTagNum plus above + */ +static void BM_lookupEventTagNum(int iters) { + + prechargeEventMap(); + + std::unordered_set::const_iterator it = set.begin(); + + for (int i = 0; i < iters; ++i) { + size_t len; + const char* name = android_lookupEventTag_len(map, &len, (*it)); + std::string Name(name, len); + const char* format = android_lookupEventFormat_len(map, &len, (*it)); + std::string Format(format, len); + StartBenchmarkTiming(); + android_lookupEventTagNum(map, Name.c_str(), Format.c_str(), + ANDROID_LOG_UNKNOWN); + StopBenchmarkTiming(); + ++it; + if (it == set.end()) it = set.begin(); + } + +} +BENCHMARK(BM_lookupEventTagNum); + +// Must be functionally identical to liblog internal __send_log_msg. +static void send_to_control(char *buf, size_t len) +{ + int sock = socket_local_client("logd", + ANDROID_SOCKET_NAMESPACE_RESERVED, + SOCK_STREAM); + if (sock < 0) return; + size_t writeLen = strlen(buf) + 1; + + ssize_t ret = TEMP_FAILURE_RETRY(write(sock, buf, writeLen)); + if (ret <= 0) { + close(sock); + return; + } + while ((ret = read(sock, buf, len)) > 0) { + if (((size_t)ret == len) || (len < PAGE_SIZE)) { + break; + } + len -= ret; + buf += ret; + + struct pollfd p = { + .fd = sock, + .events = POLLIN, + .revents = 0 + }; + + ret = poll(&p, 1, 20); + if ((ret <= 0) || !(p.revents & POLLIN)) { + break; + } + } + close(sock); +} + +static void BM_lookupEventTagNum_logd_new(int iters) { + fprintf(stderr, "WARNING: " + "This test can cause logd to grow in size and hit DOS limiter\n"); + // Make copies + static const char empty_event_log_tags[] = "# content owned by logd\n"; + static const char dev_event_log_tags_path[] = "/dev/event-log-tags"; + std::string dev_event_log_tags; + if (android::base::ReadFileToString(dev_event_log_tags_path, + &dev_event_log_tags) && + (dev_event_log_tags.length() == 0)) { + dev_event_log_tags = empty_event_log_tags; + } + static const char data_event_log_tags_path[] = "/data/misc/logd/event-log-tags"; + std::string data_event_log_tags; + if (android::base::ReadFileToString(data_event_log_tags_path, + &data_event_log_tags) && + (data_event_log_tags.length() == 0)) { + data_event_log_tags = empty_event_log_tags; + } + + for (int i = 0; i < iters; ++i) { + 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); + StartBenchmarkTiming(); + send_to_control(buffer, sizeof(buffer)); + StopBenchmarkTiming(); + } + + // Restore copies (logd still know about them, until crash or reboot) + if (dev_event_log_tags.length() && + !android::base::WriteStringToFile(dev_event_log_tags, + dev_event_log_tags_path)) { + fprintf(stderr, "WARNING: " + "failed to restore %s\n", dev_event_log_tags_path); + } + if (data_event_log_tags.length() && + !android::base::WriteStringToFile(data_event_log_tags, + data_event_log_tags_path)) { + fprintf(stderr, "WARNING: " + "failed to restore %s\n", data_event_log_tags_path); + } + fprintf(stderr, "WARNING: " + "Restarting logd to make it forget what we just did\n"); + system("stop logd ; start logd"); +} +BENCHMARK(BM_lookupEventTagNum_logd_new); + +static void BM_lookupEventTagNum_logd_existing(int iters) { + prechargeEventMap(); + + std::unordered_set::const_iterator it = set.begin(); + + for (int i = 0; i < iters; ++i) { + size_t len; + const char* name = android_lookupEventTag_len(map, &len, (*it)); + std::string Name(name, len); + const char* format = android_lookupEventFormat_len(map, &len, (*it)); + std::string Format(format, len); + + char buffer[256]; + snprintf(buffer, sizeof(buffer), + "getEventTag name=%s format=\"%s\"", + Name.c_str(), Format.c_str()); + + StartBenchmarkTiming(); + send_to_control(buffer, sizeof(buffer)); + StopBenchmarkTiming(); + ++it; + if (it == set.end()) it = set.begin(); + } +} +BENCHMARK(BM_lookupEventTagNum_logd_existing); diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index 8b9f0f0eb..5faf8e162 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -2929,3 +2929,19 @@ TEST(liblog, __android_log_ratelimit) { } // Do not test default seconds, to allow liblog to tune freely } + +TEST(liblog, android_lookupEventTagNum) { +#ifdef __ANDROID__ + EventTagMap* map = android_openEventTagMap(NULL); + EXPECT_TRUE(NULL != map); + std::string Name = android::base::StringPrintf("a%d", getpid()); + int tag = android_lookupEventTagNum(map, Name.c_str(), "(new|1)", ANDROID_LOG_UNKNOWN); + android_closeEventTagMap(map); + if (tag == -1) system("tail -3 /dev/event-log-tags >&2"); + EXPECT_NE(-1, tag); + EXPECT_NE(0, tag); + EXPECT_GT(UINT32_MAX, (unsigned)tag); +#else + GTEST_LOG_(INFO) << "This test does nothing.\n"; +#endif +} diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index 0db33b755..adf583b81 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -48,7 +48,7 @@ static void send_to_control(char* buf, size_t len) if (write(sock, buf, strlen(buf) + 1) > 0) { ssize_t ret; while ((ret = read(sock, buf, len)) > 0) { - if ((size_t)ret == len) { + if (((size_t)ret == len) || (len < PAGE_SIZE)) { break; } len -= ret;