From d917514bd6b270df431ea4e781a865764d406120 Mon Sep 17 00:00:00 2001 From: Christopher Ferris Date: Thu, 22 Oct 2015 13:34:48 -0700 Subject: [PATCH 01/65] Fix incorrect check of descsz value. Bug: 25187394 (cherry picked from commit 1fa55234d6773e09e3bb934419b5b6cc0df981c9) Change-Id: Idbc9071e8b2b25a062c4e94118808d6e19d443d9 --- debuggerd/elf_utils.cpp | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/debuggerd/elf_utils.cpp b/debuggerd/elf_utils.cpp index 5ea03e752..65c190479 100644 --- a/debuggerd/elf_utils.cpp +++ b/debuggerd/elf_utils.cpp @@ -63,10 +63,10 @@ static bool get_build_id( if (nhdr.n_type == NT_GNU_BUILD_ID) { // Skip the name (which is the owner and should be "GNU"). addr += NOTE_ALIGN(nhdr.n_namesz); - uint8_t build_id_data[128]; - if (nhdr.n_namesz > sizeof(build_id_data)) { - ALOGE("Possible corrupted note, name size value is too large: %u", - nhdr.n_namesz); + uint8_t build_id_data[160]; + if (nhdr.n_descsz > sizeof(build_id_data)) { + ALOGE("Possible corrupted note, desc size value is too large: %u", + nhdr.n_descsz); return false; } if (backtrace->Read(addr, build_id_data, nhdr.n_descsz) != nhdr.n_descsz) { From 36b24a4a20d7d1e9fee5ff14f21e9876e57db2ca Mon Sep 17 00:00:00 2001 From: Dan Willemsen Date: Thu, 22 Oct 2015 13:04:22 -0700 Subject: [PATCH 02/65] Remove __DATE__/__TIME__ from init and debuggerd Keeping these means that every build has different init and debuggerd binaries, even if the source was the same. So OTAs that don't touch these sources would still need to update the binaries. Both of these messages are only informational, so can be safely removed. Bootchart already encodes build-specific information from the system properties. Bug: 24204119 Change-Id: I7ebd65a20a3e031e7528c9f741616e20b3cd7446 (cherry picked from commit 30622bbb209db187f6851e4cf0cdaa147c2fca9f) --- debuggerd/debuggerd.cpp | 2 +- init/bootchart.cpp | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/debuggerd/debuggerd.cpp b/debuggerd/debuggerd.cpp index b84a4e587..9c8a41e61 100644 --- a/debuggerd/debuggerd.cpp +++ b/debuggerd/debuggerd.cpp @@ -538,7 +538,7 @@ static int do_server() { return 1; fcntl(s, F_SETFD, FD_CLOEXEC); - ALOGI("debuggerd: " __DATE__ " " __TIME__ "\n"); + ALOGI("debuggerd: starting\n"); for (;;) { sockaddr addr; diff --git a/init/bootchart.cpp b/init/bootchart.cpp index 95687cbd0..df8359dad 100644 --- a/init/bootchart.cpp +++ b/init/bootchart.cpp @@ -89,7 +89,7 @@ static void log_header() { if (out == NULL) { return; } - fprintf(out, "version = Android init 0.8 " __TIME__ "\n"); + fprintf(out, "version = Android init 0.8\n"); fprintf(out, "title = Boot chart for Android (%s)\n", date); fprintf(out, "system.uname = %s %s %s %s\n", uts.sysname, uts.release, uts.version, uts.machine); fprintf(out, "system.release = %s\n", fingerprint); From 653316adf1a4c5dbffb832969ff2f8d88db270a7 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 12 Oct 2015 13:45:51 -0700 Subject: [PATCH 03/65] logd: pruning time horizon Estimate a time horizon of ten fold for worst UID pruning Bug: 25453210 Bug: 24782000 Change-Id: I7118deb6d42531c68ed2ac2a59c57b0580b942cc --- logd/LogBuffer.cpp | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 559fa2e65..d72a78c0f 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -435,7 +435,10 @@ void LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { worst_sizes = sorted[0]->getSizes(); // Calculate threshold as 12.5% of available storage size_t threshold = log_buffer_size(id) / 8; - if (worst_sizes > threshold) { + if ((worst_sizes > threshold) + // Allow time horizon to extend roughly tenfold, assume + // average entry length is 100 characters. + && (worst_sizes > (10 * sorted[0]->getDropped()))) { worst = sorted[0]->getKey(); second_worst_sizes = sorted[1]->getSizes(); if (second_worst_sizes < threshold) { From 4fd82100ccbda29139c3cf5f7001e8b9892198c9 Mon Sep 17 00:00:00 2001 From: William Luh Date: Thu, 13 Aug 2015 10:41:58 -0700 Subject: [PATCH 04/65] Add macro to call event logger for errors. DO NOT MERGE Bug:23180694 Change-Id: I566a290334345f48013029534efef3e08e726e40 --- include/log/log.h | 9 ++++ liblog/Android.mk | 2 +- liblog/log_event_write.c | 88 ++++++++++++++++++++++++++++++++++++++++ 3 files changed, 98 insertions(+), 1 deletion(-) create mode 100644 liblog/log_event_write.c diff --git a/include/log/log.h b/include/log/log.h index 7faddea91..d3df5bd03 100644 --- a/include/log/log.h +++ b/include/log/log.h @@ -531,6 +531,12 @@ typedef enum { #define android_btWriteLog(tag, type, payload, len) \ __android_log_btwrite(tag, type, payload, len) +#define android_errorWriteLog(tag, subTag) \ + __android_log_error_write(tag, subTag, -1, NULL, 0) + +#define android_errorWriteWithInfoLog(tag, subTag, uid, data, dataLen) \ + __android_log_error_write(tag, subTag, uid, data, dataLen) + // TODO: remove these prototypes and their users #define android_testLog(prio, tag) (1) #define android_writevLog(vec,num) do{}while(0) @@ -549,6 +555,9 @@ typedef enum { LOG_ID_MAX } log_id_t; +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen); + /* * Send a simple string to the log. */ diff --git a/liblog/Android.mk b/liblog/Android.mk index 6bfb11966..ab0463796 100644 --- a/liblog/Android.mk +++ b/liblog/Android.mk @@ -16,7 +16,7 @@ LOCAL_PATH := $(my-dir) include $(CLEAR_VARS) -liblog_sources := logd_write.c +liblog_sources := logd_write.c log_event_write.c # some files must not be compiled when building against Mingw # they correspond to features not used by our host development tools diff --git a/liblog/log_event_write.c b/liblog/log_event_write.c new file mode 100644 index 000000000..0bc42d548 --- /dev/null +++ b/liblog/log_event_write.c @@ -0,0 +1,88 @@ +/* + * Copyright (C) 2015 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 + +#define MAX_EVENT_PAYLOAD 512 +#define MAX_SUBTAG_LEN 32 + +static inline void copy4LE(uint8_t *buf, size_t pos, int val) +{ + buf[pos] = val & 0xFF; + buf[pos+1] = (val >> 8) & 0xFF; + buf[pos+2] = (val >> 16) & 0xFF; + buf[pos+3] = (val >> 24) & 0xFF; +} + +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen) +{ + uint8_t buf[MAX_EVENT_PAYLOAD]; + size_t pos = 0; + uint32_t subTagLen = 0; + uint32_t roomLeftForData = 0; + + if ((subTag == NULL) || ((data == NULL) && (dataLen != 0))) return -EINVAL; + + subTagLen = strlen(subTag); + + // Truncate subtags that are too long. + subTagLen = subTagLen > MAX_SUBTAG_LEN ? MAX_SUBTAG_LEN : subTagLen; + + // Truncate dataLen if it is too long. + roomLeftForData = MAX_EVENT_PAYLOAD - + (1 + // EVENT_TYPE_LIST + 1 + // Number of elements in list + 1 + // EVENT_TYPE_STRING + sizeof(subTagLen) + + subTagLen + + 1 + // EVENT_TYPE_INT + sizeof(uid) + + 1 + // EVENT_TYPE_STRING + sizeof(dataLen)); + dataLen = dataLen > roomLeftForData ? roomLeftForData : dataLen; + + buf[pos++] = EVENT_TYPE_LIST; + buf[pos++] = 3; // Number of elements in the list (subTag, uid, data) + + // Write sub tag. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, subTagLen); + pos += 4; + memcpy(&buf[pos], subTag, subTagLen); + pos += subTagLen; + + // Write UID. + buf[pos++] = EVENT_TYPE_INT; + copy4LE(buf, pos, uid); + pos += 4; + + // Write data. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, dataLen); + pos += 4; + if (dataLen != 0) + { + memcpy(&buf[pos], data, dataLen); + pos += dataLen; + } + + return __android_log_bwrite(tag, buf, pos); +} From f34258fa9b5b066d8eb1d6e51baf23d1e0d4c718 Mon Sep 17 00:00:00 2001 From: William Luh Date: Thu, 13 Aug 2015 10:41:58 -0700 Subject: [PATCH 05/65] Add macro to call event logger for errors. DO NOT MERGE Bug:23180694 Change-Id: I566a290334345f48013029534efef3e08e726e40 --- include/log/log.h | 9 + liblog/Android.mk | 2 +- liblog/log_event_write.c | 88 ++++++++ liblog/tests/liblog_test.cpp | 395 +++++++++++++++++++++++++++++++++++ 4 files changed, 493 insertions(+), 1 deletion(-) create mode 100644 liblog/log_event_write.c diff --git a/include/log/log.h b/include/log/log.h index ace12d631..e3b7ec1bb 100644 --- a/include/log/log.h +++ b/include/log/log.h @@ -534,6 +534,12 @@ typedef enum { #define android_btWriteLog(tag, type, payload, len) \ __android_log_btwrite(tag, type, payload, len) +#define android_errorWriteLog(tag, subTag) \ + __android_log_error_write(tag, subTag, -1, NULL, 0) + +#define android_errorWriteWithInfoLog(tag, subTag, uid, data, dataLen) \ + __android_log_error_write(tag, subTag, uid, data, dataLen) + // TODO: remove these prototypes and their users #define android_testLog(prio, tag) (1) #define android_writevLog(vec,num) do{}while(0) @@ -557,6 +563,9 @@ typedef enum log_id { #define sizeof_log_id_t sizeof(typeof_log_id_t) #define typeof_log_id_t unsigned char +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen); + /* * Send a simple string to the log. */ diff --git a/liblog/Android.mk b/liblog/Android.mk index a4e5f5ebd..1a63761cf 100644 --- a/liblog/Android.mk +++ b/liblog/Android.mk @@ -17,7 +17,7 @@ LOCAL_PATH := $(my-dir) include $(CLEAR_VARS) ifneq ($(TARGET_USES_LOGD),false) -liblog_sources := logd_write.c +liblog_sources := logd_write.c log_event_write.c else liblog_sources := logd_write_kern.c endif diff --git a/liblog/log_event_write.c b/liblog/log_event_write.c new file mode 100644 index 000000000..0bc42d548 --- /dev/null +++ b/liblog/log_event_write.c @@ -0,0 +1,88 @@ +/* + * Copyright (C) 2015 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 + +#define MAX_EVENT_PAYLOAD 512 +#define MAX_SUBTAG_LEN 32 + +static inline void copy4LE(uint8_t *buf, size_t pos, int val) +{ + buf[pos] = val & 0xFF; + buf[pos+1] = (val >> 8) & 0xFF; + buf[pos+2] = (val >> 16) & 0xFF; + buf[pos+3] = (val >> 24) & 0xFF; +} + +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen) +{ + uint8_t buf[MAX_EVENT_PAYLOAD]; + size_t pos = 0; + uint32_t subTagLen = 0; + uint32_t roomLeftForData = 0; + + if ((subTag == NULL) || ((data == NULL) && (dataLen != 0))) return -EINVAL; + + subTagLen = strlen(subTag); + + // Truncate subtags that are too long. + subTagLen = subTagLen > MAX_SUBTAG_LEN ? MAX_SUBTAG_LEN : subTagLen; + + // Truncate dataLen if it is too long. + roomLeftForData = MAX_EVENT_PAYLOAD - + (1 + // EVENT_TYPE_LIST + 1 + // Number of elements in list + 1 + // EVENT_TYPE_STRING + sizeof(subTagLen) + + subTagLen + + 1 + // EVENT_TYPE_INT + sizeof(uid) + + 1 + // EVENT_TYPE_STRING + sizeof(dataLen)); + dataLen = dataLen > roomLeftForData ? roomLeftForData : dataLen; + + buf[pos++] = EVENT_TYPE_LIST; + buf[pos++] = 3; // Number of elements in the list (subTag, uid, data) + + // Write sub tag. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, subTagLen); + pos += 4; + memcpy(&buf[pos], subTag, subTagLen); + pos += subTagLen; + + // Write UID. + buf[pos++] = EVENT_TYPE_INT; + copy4LE(buf, pos, uid); + pos += 4; + + // Write data. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, dataLen); + pos += 4; + if (dataLen != 0) + { + memcpy(&buf[pos], data, dataLen); + pos += dataLen; + } + + return __android_log_bwrite(tag, buf, pos); +} diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index 393e2cd63..b43a90295 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -682,3 +682,398 @@ TEST(liblog, filterRule) { android_log_format_free(p_format); } + +static inline int32_t get4LE(const char* src) +{ + return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__typical) { + const int TAG = 123456781; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + eventData += strlen(SUBTAG); + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ(DATA_LEN, get4LE(eventData)); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, DATA_LEN)) { + continue; + } + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__data_too_large) { + const int TAG = 123456782; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = sizeof(max_payload_buf); + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + char *original = eventData; + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + eventData += strlen(SUBTAG); + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + size_t dataLen = get4LE(eventData); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, dataLen)) { + continue; + } + eventData += dataLen; + + // 4 bytes for the tag, and 512 bytes for the log since the max_payload_buf should be + // truncated. + ASSERT_EQ(4 + 512, eventData - original); + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__null_data) { + const int TAG = 123456783; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_GT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, NULL, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag == TAG) { + // This tag should not have been written because the data was null + count++; + break; + } + } + + EXPECT_EQ(0, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__subtag_too_long) { + const int TAG = 123456784; + const char SUBTAG[] = "abcdefghijklmnopqrstuvwxyz now i know my abc"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + // The subtag is longer than 32 and should be truncated to that. + ASSERT_EQ(32, get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, 32)) { + continue; + } + eventData += 32; + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ(DATA_LEN, get4LE(eventData)); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, DATA_LEN)) { + continue; + } + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteLog__android_logger_list_read__success) { + const int TAG = 123456785; + const char SUBTAG[] = "test-subtag"; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteLog(TAG, SUBTAG)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteLog__android_logger_list_read__null_subtag) { + const int TAG = 123456786; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_GT(0, android_errorWriteLog(TAG, NULL)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag == TAG) { + // This tag should not have been written because the data was null + count++; + break; + } + } + + EXPECT_EQ(0, count); + + android_logger_list_close(logger_list); +} From 9a86c283cd4d3b63c831779eec71a9841951ad81 Mon Sep 17 00:00:00 2001 From: William Luh Date: Thu, 13 Aug 2015 10:41:58 -0700 Subject: [PATCH 06/65] Add macro to call event logger for errors. DO NOT MERGE Bug:23180694 Change-Id: I566a290334345f48013029534efef3e08e726e40 --- include/log/log.h | 9 + liblog/Android.mk | 2 +- liblog/log_event_write.c | 88 ++++++++ liblog/tests/liblog_test.cpp | 395 +++++++++++++++++++++++++++++++++++ 4 files changed, 493 insertions(+), 1 deletion(-) create mode 100644 liblog/log_event_write.c diff --git a/include/log/log.h b/include/log/log.h index ace12d631..e3b7ec1bb 100644 --- a/include/log/log.h +++ b/include/log/log.h @@ -534,6 +534,12 @@ typedef enum { #define android_btWriteLog(tag, type, payload, len) \ __android_log_btwrite(tag, type, payload, len) +#define android_errorWriteLog(tag, subTag) \ + __android_log_error_write(tag, subTag, -1, NULL, 0) + +#define android_errorWriteWithInfoLog(tag, subTag, uid, data, dataLen) \ + __android_log_error_write(tag, subTag, uid, data, dataLen) + // TODO: remove these prototypes and their users #define android_testLog(prio, tag) (1) #define android_writevLog(vec,num) do{}while(0) @@ -557,6 +563,9 @@ typedef enum log_id { #define sizeof_log_id_t sizeof(typeof_log_id_t) #define typeof_log_id_t unsigned char +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen); + /* * Send a simple string to the log. */ diff --git a/liblog/Android.mk b/liblog/Android.mk index a4e5f5ebd..1a63761cf 100644 --- a/liblog/Android.mk +++ b/liblog/Android.mk @@ -17,7 +17,7 @@ LOCAL_PATH := $(my-dir) include $(CLEAR_VARS) ifneq ($(TARGET_USES_LOGD),false) -liblog_sources := logd_write.c +liblog_sources := logd_write.c log_event_write.c else liblog_sources := logd_write_kern.c endif diff --git a/liblog/log_event_write.c b/liblog/log_event_write.c new file mode 100644 index 000000000..0bc42d548 --- /dev/null +++ b/liblog/log_event_write.c @@ -0,0 +1,88 @@ +/* + * Copyright (C) 2015 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 + +#define MAX_EVENT_PAYLOAD 512 +#define MAX_SUBTAG_LEN 32 + +static inline void copy4LE(uint8_t *buf, size_t pos, int val) +{ + buf[pos] = val & 0xFF; + buf[pos+1] = (val >> 8) & 0xFF; + buf[pos+2] = (val >> 16) & 0xFF; + buf[pos+3] = (val >> 24) & 0xFF; +} + +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen) +{ + uint8_t buf[MAX_EVENT_PAYLOAD]; + size_t pos = 0; + uint32_t subTagLen = 0; + uint32_t roomLeftForData = 0; + + if ((subTag == NULL) || ((data == NULL) && (dataLen != 0))) return -EINVAL; + + subTagLen = strlen(subTag); + + // Truncate subtags that are too long. + subTagLen = subTagLen > MAX_SUBTAG_LEN ? MAX_SUBTAG_LEN : subTagLen; + + // Truncate dataLen if it is too long. + roomLeftForData = MAX_EVENT_PAYLOAD - + (1 + // EVENT_TYPE_LIST + 1 + // Number of elements in list + 1 + // EVENT_TYPE_STRING + sizeof(subTagLen) + + subTagLen + + 1 + // EVENT_TYPE_INT + sizeof(uid) + + 1 + // EVENT_TYPE_STRING + sizeof(dataLen)); + dataLen = dataLen > roomLeftForData ? roomLeftForData : dataLen; + + buf[pos++] = EVENT_TYPE_LIST; + buf[pos++] = 3; // Number of elements in the list (subTag, uid, data) + + // Write sub tag. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, subTagLen); + pos += 4; + memcpy(&buf[pos], subTag, subTagLen); + pos += subTagLen; + + // Write UID. + buf[pos++] = EVENT_TYPE_INT; + copy4LE(buf, pos, uid); + pos += 4; + + // Write data. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, dataLen); + pos += 4; + if (dataLen != 0) + { + memcpy(&buf[pos], data, dataLen); + pos += dataLen; + } + + return __android_log_bwrite(tag, buf, pos); +} diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index 393e2cd63..b43a90295 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -682,3 +682,398 @@ TEST(liblog, filterRule) { android_log_format_free(p_format); } + +static inline int32_t get4LE(const char* src) +{ + return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__typical) { + const int TAG = 123456781; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + eventData += strlen(SUBTAG); + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ(DATA_LEN, get4LE(eventData)); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, DATA_LEN)) { + continue; + } + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__data_too_large) { + const int TAG = 123456782; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = sizeof(max_payload_buf); + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + char *original = eventData; + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + eventData += strlen(SUBTAG); + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + size_t dataLen = get4LE(eventData); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, dataLen)) { + continue; + } + eventData += dataLen; + + // 4 bytes for the tag, and 512 bytes for the log since the max_payload_buf should be + // truncated. + ASSERT_EQ(4 + 512, eventData - original); + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__null_data) { + const int TAG = 123456783; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_GT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, NULL, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag == TAG) { + // This tag should not have been written because the data was null + count++; + break; + } + } + + EXPECT_EQ(0, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__subtag_too_long) { + const int TAG = 123456784; + const char SUBTAG[] = "abcdefghijklmnopqrstuvwxyz now i know my abc"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + // The subtag is longer than 32 and should be truncated to that. + ASSERT_EQ(32, get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, 32)) { + continue; + } + eventData += 32; + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ(DATA_LEN, get4LE(eventData)); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, DATA_LEN)) { + continue; + } + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteLog__android_logger_list_read__success) { + const int TAG = 123456785; + const char SUBTAG[] = "test-subtag"; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_LT(0, android_errorWriteLog(TAG, SUBTAG)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteLog__android_logger_list_read__null_subtag) { + const int TAG = 123456786; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + ASSERT_GT(0, android_errorWriteLog(TAG, NULL)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag == TAG) { + // This tag should not have been written because the data was null + count++; + break; + } + } + + EXPECT_EQ(0, count); + + android_logger_list_close(logger_list); +} From f6891c025af9699bc2951de3e1de02f26ddf633d Mon Sep 17 00:00:00 2001 From: William Luh Date: Thu, 13 Aug 2015 10:41:58 -0700 Subject: [PATCH 07/65] Add macro to call event logger for errors. Bug:23180694 Change-Id: I566a290334345f48013029534efef3e08e726e40 --- include/log/log.h | 9 + liblog/Android.mk | 2 +- liblog/log_event_write.c | 88 ++++++++ liblog/tests/liblog_test.cpp | 396 +++++++++++++++++++++++++++++++++++ 4 files changed, 494 insertions(+), 1 deletion(-) create mode 100644 liblog/log_event_write.c diff --git a/include/log/log.h b/include/log/log.h index 0b175749c..1cdf7bc49 100644 --- a/include/log/log.h +++ b/include/log/log.h @@ -563,6 +563,12 @@ typedef enum { #define android_btWriteLog(tag, type, payload, len) \ __android_log_btwrite(tag, type, payload, len) +#define android_errorWriteLog(tag, subTag) \ + __android_log_error_write(tag, subTag, -1, NULL, 0) + +#define android_errorWriteWithInfoLog(tag, subTag, uid, data, dataLen) \ + __android_log_error_write(tag, subTag, uid, data, dataLen) + /* * IF_ALOG uses android_testLog, but IF_ALOG can be overridden. * android_testLog will remain constant in its purpose as a wrapper @@ -612,6 +618,9 @@ typedef enum log_id { */ int __android_log_is_loggable(int prio, const char *tag, int def); +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen); + /* * Send a simple string to the log. */ diff --git a/liblog/Android.mk b/liblog/Android.mk index d7766f544..115dd79b3 100644 --- a/liblog/Android.mk +++ b/liblog/Android.mk @@ -25,7 +25,7 @@ include $(CLEAR_VARS) liblog_cflags := -DLIBLOG_LOG_TAG=1005 ifneq ($(TARGET_USES_LOGD),false) -liblog_sources := logd_write.c +liblog_sources := logd_write.c log_event_write.c else liblog_sources := logd_write_kern.c endif diff --git a/liblog/log_event_write.c b/liblog/log_event_write.c new file mode 100644 index 000000000..0bc42d548 --- /dev/null +++ b/liblog/log_event_write.c @@ -0,0 +1,88 @@ +/* + * Copyright (C) 2015 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 + +#define MAX_EVENT_PAYLOAD 512 +#define MAX_SUBTAG_LEN 32 + +static inline void copy4LE(uint8_t *buf, size_t pos, int val) +{ + buf[pos] = val & 0xFF; + buf[pos+1] = (val >> 8) & 0xFF; + buf[pos+2] = (val >> 16) & 0xFF; + buf[pos+3] = (val >> 24) & 0xFF; +} + +int __android_log_error_write(int tag, const char *subTag, int32_t uid, const char *data, + uint32_t dataLen) +{ + uint8_t buf[MAX_EVENT_PAYLOAD]; + size_t pos = 0; + uint32_t subTagLen = 0; + uint32_t roomLeftForData = 0; + + if ((subTag == NULL) || ((data == NULL) && (dataLen != 0))) return -EINVAL; + + subTagLen = strlen(subTag); + + // Truncate subtags that are too long. + subTagLen = subTagLen > MAX_SUBTAG_LEN ? MAX_SUBTAG_LEN : subTagLen; + + // Truncate dataLen if it is too long. + roomLeftForData = MAX_EVENT_PAYLOAD - + (1 + // EVENT_TYPE_LIST + 1 + // Number of elements in list + 1 + // EVENT_TYPE_STRING + sizeof(subTagLen) + + subTagLen + + 1 + // EVENT_TYPE_INT + sizeof(uid) + + 1 + // EVENT_TYPE_STRING + sizeof(dataLen)); + dataLen = dataLen > roomLeftForData ? roomLeftForData : dataLen; + + buf[pos++] = EVENT_TYPE_LIST; + buf[pos++] = 3; // Number of elements in the list (subTag, uid, data) + + // Write sub tag. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, subTagLen); + pos += 4; + memcpy(&buf[pos], subTag, subTagLen); + pos += subTagLen; + + // Write UID. + buf[pos++] = EVENT_TYPE_INT; + copy4LE(buf, pos, uid); + pos += 4; + + // Write data. + buf[pos++] = EVENT_TYPE_STRING; + copy4LE(buf, pos, dataLen); + pos += 4; + if (dataLen != 0) + { + memcpy(&buf[pos], data, dataLen); + pos += dataLen; + } + + return __android_log_bwrite(tag, buf, pos); +} diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp index abe023974..c98704139 100644 --- a/liblog/tests/liblog_test.cpp +++ b/liblog/tests/liblog_test.cpp @@ -17,6 +17,7 @@ #include #include #include +#include #include #include @@ -876,3 +877,398 @@ TEST(liblog, is_loggable) { property_set(key, hold[2]); property_set(key + base_offset, hold[3]); } + +static inline int32_t get4LE(const char* src) +{ + return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__typical) { + const int TAG = 123456781; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + eventData += strlen(SUBTAG); + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ(DATA_LEN, get4LE(eventData)); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, DATA_LEN)) { + continue; + } + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__data_too_large) { + const int TAG = 123456782; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = sizeof(max_payload_buf); + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + char *original = eventData; + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + eventData += strlen(SUBTAG); + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + size_t dataLen = get4LE(eventData); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, dataLen)) { + continue; + } + eventData += dataLen; + + // 4 bytes for the tag, and 512 bytes for the log since the max_payload_buf should be + // truncated. + ASSERT_EQ(4 + 512, eventData - original); + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__null_data) { + const int TAG = 123456783; + const char SUBTAG[] = "test-subtag"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid))); + + ASSERT_GT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, NULL, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag == TAG) { + // This tag should not have been written because the data was null + count++; + break; + } + } + + EXPECT_EQ(0, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteWithInfoLog__android_logger_list_read__subtag_too_long) { + const int TAG = 123456784; + const char SUBTAG[] = "abcdefghijklmnopqrstuvwxyz now i know my abc"; + const int UID = -1; + const int DATA_LEN = 200; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid))); + + ASSERT_LT(0, android_errorWriteWithInfoLog( + TAG, SUBTAG, UID, max_payload_buf, DATA_LEN)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + // The subtag is longer than 32 and should be truncated to that. + ASSERT_EQ(32, get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, 32)) { + continue; + } + eventData += 32; + + // Element #2: int type for uid + ASSERT_EQ(EVENT_TYPE_INT, eventData[0]); + eventData++; + + ASSERT_EQ(UID, get4LE(eventData)); + eventData += 4; + + // Element #3: string type for data + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ(DATA_LEN, get4LE(eventData)); + eventData += 4; + + if (memcmp(max_payload_buf, eventData, DATA_LEN)) { + continue; + } + + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteLog__android_logger_list_read__success) { + const int TAG = 123456785; + const char SUBTAG[] = "test-subtag"; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid))); + + ASSERT_LT(0, android_errorWriteLog(TAG, SUBTAG)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag != TAG) { + continue; + } + + // List type + ASSERT_EQ(EVENT_TYPE_LIST, eventData[0]); + eventData++; + + // Number of elements in list + ASSERT_EQ(3, eventData[0]); + eventData++; + + // Element #1: string type for subtag + ASSERT_EQ(EVENT_TYPE_STRING, eventData[0]); + eventData++; + + ASSERT_EQ((int) strlen(SUBTAG), get4LE(eventData)); + eventData +=4; + + if (memcmp(SUBTAG, eventData, strlen(SUBTAG))) { + continue; + } + ++count; + } + + EXPECT_EQ(1, count); + + android_logger_list_close(logger_list); +} + +TEST(liblog, android_errorWriteLog__android_logger_list_read__null_subtag) { + const int TAG = 123456786; + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_TRUE(NULL != (logger_list = android_logger_list_open( + LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, pid))); + + ASSERT_GT(0, android_errorWriteLog(TAG, NULL)); + + sleep(2); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + char *eventData = log_msg.msg(); + + // Tag + int tag = get4LE(eventData); + eventData += 4; + + if (tag == TAG) { + // This tag should not have been written because the data was null + count++; + break; + } + } + + EXPECT_EQ(0, count); + + android_logger_list_close(logger_list); +} From 5b0d59dde85162fa9ef3a32464c0f1b81d7e05cb Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 6 Oct 2015 08:59:02 -0700 Subject: [PATCH 08/65] logcat: continue where we left off Issue introduced as part of new logcatd functionality in commit f3555d9427425c2cba9600ceffb49305c440aa4a Faulty logic, add a gTest to confirm. Bug: 19608716 Change-Id: Ic1b97def25e03e69faae4398a3dff2ff0f88545e --- logcat/logcat.cpp | 2 +- logcat/tests/logcat_test.cpp | 134 +++++++++++++++++++++++++++++++---- 2 files changed, 120 insertions(+), 16 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index e598bb810..3d05d8ffc 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -649,7 +649,7 @@ int main(int argc, char **argv) break; case 'f': - if ((tail_time == log_time::EPOCH) && (tail_lines != 0)) { + if ((tail_time == log_time::EPOCH) && (tail_lines == 0)) { tail_time = lastLogTime(optarg); } // redirect output to a file diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp index de2db674d..9455d870e 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -15,10 +15,12 @@ */ #include +#include #include #include #include #include +#include #include #include @@ -284,7 +286,7 @@ TEST(logcat, get_size) { while (fgets(buffer, sizeof(buffer), fp)) { int size, consumed, max, payload; - char size_mult[2], consumed_mult[2]; + char size_mult[3], consumed_mult[3]; long full_size, full_consumed; size = consumed = max = payload = 0; @@ -489,12 +491,12 @@ TEST(logcat, logrotate) { static const char comm[] = "logcat -b radio -b events -b system -b main" " -d -f %s/log.txt -n 7 -r 1"; char command[sizeof(buf) + sizeof(comm)]; - sprintf(command, comm, buf); + snprintf(command, sizeof(command), comm, buf); int ret; EXPECT_FALSE((ret = system(command))); if (!ret) { - sprintf(command, "ls -s %s 2>/dev/null", buf); + snprintf(command, sizeof(command), "ls -s %s 2>/dev/null", buf); FILE *fp; EXPECT_TRUE(NULL != (fp = popen(command, "r"))); @@ -503,16 +505,12 @@ TEST(logcat, logrotate) { int count = 0; while (fgets(buffer, sizeof(buffer), fp)) { - static const char match_1[] = "4 log.txt"; - static const char match_2[] = "8 log.txt"; - static const char match_3[] = "12 log.txt"; - static const char match_4[] = "16 log.txt"; static const char total[] = "total "; + int num; + char c; - if (!strncmp(buffer, match_1, sizeof(match_1) - 1) - || !strncmp(buffer, match_2, sizeof(match_2) - 1) - || !strncmp(buffer, match_3, sizeof(match_3) - 1) - || !strncmp(buffer, match_4, sizeof(match_4) - 1)) { + if ((2 == sscanf(buffer, "%d log.tx%c", &num, &c)) && + (num <= 24)) { ++count; } else if (strncmp(buffer, total, sizeof(total) - 1)) { fprintf(stderr, "WARNING: Parse error: %s", buffer); @@ -522,7 +520,7 @@ TEST(logcat, logrotate) { EXPECT_TRUE(count == 7 || count == 8); } } - sprintf(command, "rm -rf %s", buf); + snprintf(command, sizeof(command), "rm -rf %s", buf); EXPECT_FALSE(system(command)); } @@ -534,12 +532,12 @@ TEST(logcat, logrotate_suffix) { static const char logcat_cmd[] = "logcat -b radio -b events -b system -b main" " -d -f %s/log.txt -n 10 -r 1"; char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd)]; - sprintf(command, logcat_cmd, tmp_out_dir); + snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir); int ret; EXPECT_FALSE((ret = system(command))); if (!ret) { - sprintf(command, "ls %s 2>/dev/null", tmp_out_dir); + snprintf(command, sizeof(command), "ls %s 2>/dev/null", tmp_out_dir); FILE *fp; EXPECT_TRUE(NULL != (fp = popen(command, "r"))); @@ -575,7 +573,113 @@ TEST(logcat, logrotate_suffix) { pclose(fp); EXPECT_EQ(11, log_file_count); } - sprintf(command, "rm -rf %s", tmp_out_dir); + snprintf(command, sizeof(command), "rm -rf %s", tmp_out_dir); + EXPECT_FALSE(system(command)); +} + +TEST(logcat, logrotate_continue) { + static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; + char tmp_out_dir[sizeof(tmp_out_dir_form)]; + ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); + + static const char log_filename[] = "log.txt"; + static const char logcat_cmd[] = "logcat -b all -d -f %s/%s -n 256 -r 1024"; + static const char cleanup_cmd[] = "rm -rf %s"; + char command[sizeof(tmp_out_dir) + sizeof(logcat_cmd) + sizeof(log_filename)]; + snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); + + int ret; + EXPECT_FALSE((ret = system(command))); + if (ret) { + snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); + EXPECT_FALSE(system(command)); + return; + } + FILE *fp; + snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, log_filename); + EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); + if (!fp) { + snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); + EXPECT_FALSE(system(command)); + return; + } + char *line = NULL; + char *last_line = NULL; // this line is allowed to stutter, one-line overlap + char *second_last_line = NULL; + size_t len = 0; + while (getline(&line, &len, fp) != -1) { + free(second_last_line); + second_last_line = last_line; + last_line = line; + line = NULL; + } + fclose(fp); + free(line); + if (second_last_line == NULL) { + fprintf(stderr, "No second to last line, using last, test may fail\n"); + second_last_line = last_line; + last_line = NULL; + } + free(last_line); + EXPECT_TRUE(NULL != second_last_line); + if (!second_last_line) { + snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); + EXPECT_FALSE(system(command)); + return; + } + // re-run the command, it should only add a few lines more content if it + // continues where it left off. + snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); + EXPECT_FALSE((ret = system(command))); + if (ret) { + snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); + EXPECT_FALSE(system(command)); + return; + } + DIR *dir; + EXPECT_TRUE(NULL != (dir = opendir(tmp_out_dir))); + if (!dir) { + snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); + EXPECT_FALSE(system(command)); + return; + } + struct dirent *entry; + unsigned count = 0; + while ((entry = readdir(dir))) { + if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { + continue; + } + snprintf(command, sizeof(command), "%s/%s", tmp_out_dir, entry->d_name); + EXPECT_TRUE(NULL != ((fp = fopen(command, "r")))); + if (!fp) { + fprintf(stderr, "%s ?\n", command); + continue; + } + line = NULL; + size_t number = 0; + while (getline(&line, &len, fp) != -1) { + ++number; + if (!strcmp(line, second_last_line)) { + EXPECT_TRUE(++count <= 1); + fprintf(stderr, "%s(%zu):\n", entry->d_name, number); + } + } + fclose(fp); + free(line); + unlink(command); + } + closedir(dir); + if (count > 1) { + char *brk = strpbrk(second_last_line, "\r\n"); + if (!brk) { + brk = second_last_line + strlen(second_last_line); + } + fprintf(stderr, "\"%.*s\" occured %u times\n", + (int)(brk - second_last_line), second_last_line, count); + } + free(second_last_line); + + snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); EXPECT_FALSE(system(command)); } From 540cfe8e6ba6963f7d6b6407870aac197d1e27e6 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 26 Aug 2015 09:30:00 -0700 Subject: [PATCH 09/65] logd: klogd and Mediatek part deux (cherry pick from commit 47dba71f240624fc0fc9d39e2b91dc82ef164b39) - switch to an open coded strnrchr - validity checking on n, taglen and b values. Bug: 23517551 Change-Id: I568e25c5aa6d8474835454a0e83b19c2921b7986 --- logd/LogKlog.cpp | 28 +++++++++++++++++++++------- 1 file changed, 21 insertions(+), 7 deletions(-) diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp index febf775f2..c6109f56e 100644 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -388,6 +388,16 @@ static int convertKernelPrioToAndroidPrio(int pri) { return ANDROID_LOG_INFO; } +static const char *strnrchr(const char *s, size_t len, char c) { + const char *save = NULL; + for (;len; ++s, len--) { + if (*s == c) { + save = s; + } + } + return save; +} + // // log a message into the kernel log buffer // @@ -584,11 +594,11 @@ int LogKlog::log(const char *buf) { // eg: [143:healthd]healthd -> [143:healthd] size_t taglen = etag - tag; // Mediatek-special printk induced stutter - char *np = strrchr(tag, ']'); - if (np && (++np < etag)) { - size_t s = etag - np; - if (((s + s) < taglen) && !strncmp(np, np - 1 - s, s)) { - taglen = np - tag; + const char *mp = strnrchr(tag, ']', taglen); + if (mp && (++mp < etag)) { + size_t s = etag - mp; + if (((s + s) < taglen) && !memcmp(mp, mp - 1 - s, s)) { + taglen = mp - tag; } } // skip leading space @@ -606,15 +616,19 @@ int LogKlog::log(const char *buf) { b = 1; } size_t n = 1 + taglen + 1 + b + 1; + int rc = n; + if ((taglen > n) || (b > n)) { // Can not happen ... + rc = -EINVAL; + return rc; + } // Allocate a buffer to hold the interpreted log message - int rc = n; char *newstr = reinterpret_cast(malloc(n)); if (!newstr) { rc = -ENOMEM; return rc; } - np = newstr; + char *np = newstr; // Convert priority into single-byte Android logger priority *np = convertKernelPrioToAndroidPrio(pri); From 3f78f93302c737b454ea63bac0bb15553b953d01 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 1 Sep 2015 13:09:23 -0700 Subject: [PATCH 10/65] logd: klogd: sniff for time correction on Mediatek (cherry pick from commit 2d159bf3b597eb6defbb9e74c60a003bc9387a0a) Need some more flexibility when parsing kernel messages cluttered with extra fluff. This is the minimal relaxation we can do to the rules to ensure that we work on all possible devices and kernels when sniffing for time correction information. We want to minimize any future maintenance, keep in mind klogd is a "userdebug" or "eng" feature and is disabled in "user" builds. Manage expectations. Bug: 23517551 Change-Id: I026d074e14fb2550e728683e85a973bd87e78a9c --- logd/LogKlog.cpp | 110 +++++++++++++++++++++++++++++------------------ 1 file changed, 68 insertions(+), 42 deletions(-) diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp index c6109f56e..0965ffd55 100644 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -249,36 +249,47 @@ void LogKlog::calculateCorrection(const log_time &monotonic, correction = real - monotonic; } +static const char suspendStr[] = "PM: suspend entry "; +static const char resumeStr[] = "PM: suspend exit "; +static const char suspendedStr[] = "Suspended for "; + 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 healthd[] = "healthd: battery "; - static const char suspended[] = "Suspended for "; + static const char healthd[] = "healthd"; + static const char battery[] = ": battery "; 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, healthd, sizeof(healthd) - 1)) { + *buf = cp; + + const char *b; + if ((b = strstr(cp, suspendStr))) { + calculateCorrection(now, b + sizeof(suspendStr) - 1); + } else if ((b = strstr(cp, resumeStr))) { + calculateCorrection(now, b + sizeof(resumeStr) - 1); + } else if (((b = strstr(cp, healthd))) && ((b = strstr(b, battery)))) { + // NB: healthd is roughly 150us late, worth the price to deal with + // ntp-induced or hardware clock drift. // look for " 2???-??-?? ??:??:??.????????? ???" const char *tp; - for (tp = cp + sizeof(healthd) - 1; *tp && (*tp != '\n'); ++tp) { + for (tp = b + sizeof(battery) - 1; *tp && (*tp != '\n'); ++tp) { if ((tp[0] == ' ') && (tp[1] == '2') && (tp[5] == '-')) { calculateCorrection(now, tp + 1); break; } } - } else if (!strncmp(cp, suspended, sizeof(suspended) - 1)) { + } else if ((b = strstr(cp, suspendedStr))) { log_time real; char *endp; - real.tv_sec = strtol(cp + sizeof(suspended) - 1, &endp, 10); + real.tv_sec = strtol(b + sizeof(suspendedStr) - 1, &endp, 10); if (*endp == '.') { - real.tv_nsec = strtol(endp + 1, &endp, 10) * 1000000L; + unsigned long multiplier = NS_PER_SEC; + real.tv_nsec = 0; + while (isdigit(*++endp) && (multiplier /= 10)) { + real.tv_nsec += (*endp - '0') * multiplier; + } if (reverse) { correction -= real; } else { @@ -288,7 +299,6 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { } convertMonotonicToReal(now); - *buf = cp; } else { now = log_time(CLOCK_REALTIME); } @@ -310,34 +320,6 @@ pid_t LogKlog::sniffPid(const char *cp) { return 0; } -// 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; @@ -358,6 +340,50 @@ static int parseKernelPrio(const char **buf) { return pri; } +// 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, suspendStr); + if (!cp) { + cp = strstr(buf, resumeStr); + if (!cp) { + return; + } + } else { + const char *rp = strstr(buf, resumeStr); + if (rp && (rp < cp)) { + cp = rp; + } + } + + do { + --cp; + } while ((cp > buf) && (*cp != '\n')); + if (*cp == '\n') { + ++cp; + } + parseKernelPrio(&cp); + + log_time now; + sniffTime(now, &cp, true); + + char *suspended = strstr(buf, suspendedStr); + if (!suspended || (suspended > cp)) { + return; + } + cp = suspended; + + do { + --cp; + } while ((cp > buf) && (*cp != '\n')); + if (*cp == '\n') { + ++cp; + } + parseKernelPrio(&cp); + + sniffTime(now, &cp, true); +} + // Convert kernel log priority number into an Android Logger priority number static int convertKernelPrioToAndroidPrio(int pri) { switch(pri & LOG_PRIMASK) { From 26499e41ae2f81798be20ee97e494900d7eceedc Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 8 Sep 2015 07:57:27 -0700 Subject: [PATCH 11/65] liblog: logprint: printable nul (cherry pick from commit faa92e99151ccec81073cb7ded2d49458468a02d) Change-Id: I57d1f86ce040ad196c558bb72ac0464af793c214 --- liblog/logprint.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/liblog/logprint.c b/liblog/logprint.c index 97e28fdaf..b6dba2eef 100644 --- a/liblog/logprint.c +++ b/liblog/logprint.c @@ -819,7 +819,7 @@ WEAK ssize_t utf8_character_length(const char *src, size_t len) uint32_t utf32; if ((first_char & 0x80) == 0) { /* ASCII */ - return 1; + return first_char ? 1 : -1; } /* From f9e4d0b6b5559090be599a3282273d799d3499d8 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 2 Sep 2015 07:39:53 -0700 Subject: [PATCH 12/65] logd: log_strtok_r deal with nuls (cherry pick from commit ea1a24110767d6d5666fda8a19dd0b3f954068d6) Rename to log_strntok_r and change from dealing with strings to dealing with a string and an associated length. Bug: 23517551 Change-Id: Ia72f1305a53f55eeef9861ac378fb8205fd2378e --- logd/LogKlog.cpp | 82 ++++++++++++++++++++++++++++++++++-------------- logd/LogKlog.h | 2 +- logd/main.cpp | 25 ++++++++------- 3 files changed, 72 insertions(+), 37 deletions(-) diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp index 0965ffd55..f0b18da02 100644 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -39,14 +39,15 @@ static const char priority_message[] = { KMSG_PRIORITY(LOG_INFO), '\0' }; // Parsing is hard // called if we see a '<', s is the next character, returns pointer after '>' -static char *is_prio(char *s) { - if (!isdigit(*s++)) { +static char *is_prio(char *s, size_t len) { + if (!len || !isdigit(*s++)) { return NULL; } - static const size_t max_prio_len = 4; - size_t len = 0; + --len; + static const size_t max_prio_len = (len < 4) ? len : 4; + size_t priolen = 0; char c; - while (((c = *s++)) && (++len <= max_prio_len)) { + while (((c = *s++)) && (++priolen <= max_prio_len)) { if (!isdigit(c)) { return ((c == '>') && (*s == '[')) ? s : NULL; } @@ -55,16 +56,19 @@ static char *is_prio(char *s) { } // called if we see a '[', s is the next character, returns pointer after ']' -static char *is_timestamp(char *s) { - while (*s == ' ') { +static char *is_timestamp(char *s, size_t len) { + while (len && (*s == ' ')) { ++s; + --len; } - if (!isdigit(*s++)) { + if (!len || !isdigit(*s++)) { return NULL; } + --len; bool first_period = true; char c; - while ((c = *s++)) { + while (len && ((c = *s++))) { + --len; if ((c == '.') && first_period) { first_period = false; } else if (!isdigit(c)) { @@ -85,7 +89,11 @@ static char *is_timestamp(char *s) { // space is one more than of 9 #define OPEN_BRACKET_SPACE ((char)(OPEN_BRACKET_SIG | 10)) -char *log_strtok_r(char *s, char **last) { +char *log_strntok_r(char *s, size_t *len, char **last, size_t *sublen) { + *sublen = 0; + if (!*len) { + return NULL; + } if (!s) { if (!(s = *last)) { return NULL; @@ -95,6 +103,7 @@ char *log_strtok_r(char *s, char **last) { if ((*s & SIGNATURE_MASK) == LESS_THAN_SIG) { *s = (*s & ~SIGNATURE_MASK) + '0'; *--s = '<'; + ++*len; } // fixup for log signature split [, // OPEN_BRACKET_SPACE is space, OPEN_BRACKET_SIG + @@ -105,24 +114,30 @@ char *log_strtok_r(char *s, char **last) { *s = (*s & ~SIGNATURE_MASK) + '0'; } *--s = '['; + ++*len; } } - s += strspn(s, "\r\n"); + while (*len && ((*s == '\r') || (*s == '\n'))) { + ++s; + --*len; + } - if (!*s) { // no non-delimiter characters + if (!*len) { *last = NULL; return NULL; } char *peek, *tok = s; for (;;) { - char c = *s++; - switch (c) { - case '\0': + if (*len == 0) { *last = NULL; return tok; - + } + char c = *s++; + --*len; + size_t adjust; + switch (c) { case '\r': case '\n': s[-1] = '\0'; @@ -130,7 +145,7 @@ char *log_strtok_r(char *s, char **last) { return tok; case '<': - peek = is_prio(s); + peek = is_prio(s, *len); if (!peek) { break; } @@ -141,14 +156,26 @@ char *log_strtok_r(char *s, char **last) { *last = s; return tok; } + adjust = peek - s; + if (adjust > *len) { + adjust = *len; + } + *sublen += adjust; + *len -= adjust; s = peek; - if ((*s == '[') && ((peek = is_timestamp(s + 1)))) { + if ((*s == '[') && ((peek = is_timestamp(s + 1, *len - 1)))) { + adjust = peek - s; + if (adjust > *len) { + adjust = *len; + } + *sublen += adjust; + *len -= adjust; s = peek; } break; case '[': - peek = is_timestamp(s); + peek = is_timestamp(s, *len); if (!peek) { break; } @@ -163,9 +190,16 @@ char *log_strtok_r(char *s, char **last) { *last = s; return tok; } + adjust = peek - s; + if (adjust > *len) { + adjust = *len; + } + *sublen += adjust; + *len -= adjust; s = peek; break; } + ++*sublen; } // NOTREACHED } @@ -212,13 +246,13 @@ bool LogKlog::onDataAvailable(SocketClient *cli) { bool full = len == (sizeof(buffer) - 1); char *ep = buffer + len; *ep = '\0'; - len = 0; + size_t sublen; for(char *ptr = NULL, *tok = buffer; - ((tok = log_strtok_r(tok, &ptr))); + ((tok = log_strntok_r(tok, &len, &ptr, &sublen))); tok = NULL) { - if (((tok + strlen(tok)) == ep) && (retval != 0) && full) { - len = strlen(tok); - memmove(buffer, tok, len); + if (((tok + sublen) >= ep) && (retval != 0) && full) { + memmove(buffer, tok, sublen); + len = sublen; break; } if (*tok) { diff --git a/logd/LogKlog.h b/logd/LogKlog.h index 7e4fde086..b0ea8642c 100644 --- a/logd/LogKlog.h +++ b/logd/LogKlog.h @@ -21,7 +21,7 @@ #include #include "LogReader.h" -char *log_strtok_r(char *str, char **saveptr); +char *log_strntok_r(char *s, size_t *len, char **saveptr, size_t *sublen); class LogKlog : public SocketListener { LogBuffer *logbuf; diff --git a/logd/main.cpp b/logd/main.cpp index a3241d059..68d69c63e 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -286,30 +286,31 @@ static void readDmesg(LogAudit *al, LogKlog *kl) { return; } - int len = klogctl(KLOG_SIZE_BUFFER, NULL, 0); - if (len <= 0) { - return; - } - - len += 1024; // Margin for additional input race or trailing nul - std::unique_ptr buf(new char[len]); - - int rc = klogctl(KLOG_READ_ALL, buf.get(), len); + int rc = klogctl(KLOG_SIZE_BUFFER, NULL, 0); if (rc <= 0) { return; } - if (rc < len) { + size_t len = rc + 1024; // Margin for additional input race or trailing nul + std::unique_ptr buf(new char[len]); + + rc = klogctl(KLOG_READ_ALL, buf.get(), len); + if (rc <= 0) { + return; + } + + if ((size_t)rc < len) { len = rc + 1; } - buf[len - 1] = '\0'; + buf[--len] = '\0'; if (kl) { kl->synchronize(buf.get()); } + size_t sublen; for (char *ptr = NULL, *tok = buf.get(); - (rc >= 0) && ((tok = log_strtok_r(tok, &ptr))); + (rc >= 0) && ((tok = log_strntok_r(tok, &len, &ptr, &sublen))); tok = NULL) { if (al) { rc = al->log(tok); From 4efc87e5ebd7612d119cd8c09bf78b32093c258e Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Fri, 4 Sep 2015 11:37:42 -0700 Subject: [PATCH 13/65] logd: klogd deal with nuls in dmesg (cherry pick from commit 151beac76d372c5c1bd71e656a6cfbd177e36509) Switch to using string and length in all transactions, treating trailing nuls the same as spaces. ToDo: change dumpstate (bugreport) to use logcat -b printable _regardless_ Bug: 23517551 Change-Id: I42162365e6bf8ed79d356e7b689a673902116fdb --- logd/LogAudit.cpp | 6 +- logd/LogAudit.h | 2 +- logd/LogKlog.cpp | 216 ++++++++++++++++++++++++++++------------------ logd/LogKlog.h | 11 +-- logd/main.cpp | 6 +- 5 files changed, 147 insertions(+), 94 deletions(-) diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp index 4b3547ce1..7db17d1df 100644 --- a/logd/LogAudit.cpp +++ b/logd/LogAudit.cpp @@ -239,9 +239,9 @@ int LogAudit::logPrint(const char *fmt, ...) { return rc; } -int LogAudit::log(char *buf) { +int LogAudit::log(char *buf, size_t len) { char *audit = strstr(buf, " audit("); - if (!audit) { + if (!audit || (audit >= &buf[len])) { return 0; } @@ -249,7 +249,7 @@ int LogAudit::log(char *buf) { int rc; char *type = strstr(buf, "type="); - if (type) { + if (type && (type < &buf[len])) { rc = logPrint("%s %s", type, audit + 1); } else { rc = logPrint("%s", audit + 1); diff --git a/logd/LogAudit.h b/logd/LogAudit.h index f977be983..23428228a 100644 --- a/logd/LogAudit.h +++ b/logd/LogAudit.h @@ -28,7 +28,7 @@ class LogAudit : public SocketListener { public: LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg); - int log(char *buf); + int log(char *buf, size_t len); protected: virtual bool onDataAvailable(SocketClient *cli); diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp index f0b18da02..242d7a0a4 100644 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -81,6 +81,8 @@ static char *is_timestamp(char *s, size_t len) { // Like strtok_r with "\r\n" except that we look for log signatures (regex) // \(\(<[0-9]\{1,4\}>\)\([[] *[0-9]+[.][0-9]+[]] \)\{0,1\}\|[[] *[0-9]+[.][0-9]+[]] \) // and split if we see a second one without a newline. +// We allow nuls in content, monitoring the overall length and sub-length of +// the discovered tokens. #define SIGNATURE_MASK 0xF0 // following ('0' to '9' masked with ~SIGNATURE_MASK) added to signature @@ -256,7 +258,7 @@ bool LogKlog::onDataAvailable(SocketClient *cli) { break; } if (*tok) { - log(tok); + log(tok, sublen); } } } @@ -266,9 +268,11 @@ bool LogKlog::onDataAvailable(SocketClient *cli) { void LogKlog::calculateCorrection(const log_time &monotonic, - const char *real_string) { + const char *real_string, + size_t len) { log_time real; - if (!real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC")) { + const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC"); + if (!ep || (ep > &real_string[len])) { return; } // kernel report UTC, log_time::strptime is localtime from calendar. @@ -287,41 +291,79 @@ static const char suspendStr[] = "PM: suspend entry "; static const char resumeStr[] = "PM: suspend exit "; static const char suspendedStr[] = "Suspended for "; -void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { - const char *cp; - if ((cp = now.strptime(*buf, "[ %s.%q]"))) { +static const char *strnstr(const char *s, size_t len, const char *needle) { + char c; + + if (!len) { + return NULL; + } + if ((c = *needle++) != 0) { + size_t needleLen = strlen(needle); + do { + do { + if (len <= needleLen) { + return NULL; + } + --len; + } while (*s++ != c); + } while (memcmp(s, needle, needleLen) != 0); + s--; + } + return s; +} + +void LogKlog::sniffTime(log_time &now, + const char **buf, size_t len, + bool reverse) { + const char *cp = now.strptime(*buf, "[ %s.%q]"); + if (cp && (cp >= &(*buf)[len])) { + cp = NULL; + } + len -= cp - *buf; + if (cp) { static const char healthd[] = "healthd"; static const char battery[] = ": battery "; - if (isspace(*cp)) { + if (len && isspace(*cp)) { ++cp; + --len; } *buf = cp; const char *b; - if ((b = strstr(cp, suspendStr))) { - calculateCorrection(now, b + sizeof(suspendStr) - 1); - } else if ((b = strstr(cp, resumeStr))) { - calculateCorrection(now, b + sizeof(resumeStr) - 1); - } else if (((b = strstr(cp, healthd))) && ((b = strstr(b, battery)))) { + if (((b = strnstr(cp, len, suspendStr))) + && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { + len -= b - cp; + calculateCorrection(now, b, len); + } else if (((b = strnstr(cp, len, resumeStr))) + && ((size_t)((b += sizeof(resumeStr) - 1) - cp) < len)) { + len -= b - cp; + calculateCorrection(now, b, len); + } else if (((b = strnstr(cp, len, healthd))) + && ((size_t)((b += sizeof(healthd) - 1) - cp) < len) + && ((b = strnstr(b, len -= b - cp, battery))) + && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) { + len -= b - cp; // NB: healthd is roughly 150us late, worth the price to deal with // ntp-induced or hardware clock drift. // look for " 2???-??-?? ??:??:??.????????? ???" - const char *tp; - for (tp = b + sizeof(battery) - 1; *tp && (*tp != '\n'); ++tp) { - if ((tp[0] == ' ') && (tp[1] == '2') && (tp[5] == '-')) { - calculateCorrection(now, tp + 1); + for (; len && *b && (*b != '\n'); ++b, --len) { + if ((b[0] == ' ') && (b[1] == '2') && (b[5] == '-')) { + calculateCorrection(now, b + 1, len - 1); break; } } - } else if ((b = strstr(cp, suspendedStr))) { + } else if (((b = strnstr(cp, len, suspendedStr))) + && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) { + len -= b - cp; log_time real; char *endp; - real.tv_sec = strtol(b + sizeof(suspendedStr) - 1, &endp, 10); - if (*endp == '.') { + real.tv_sec = strtol(b, &endp, 10); + if ((*endp == '.') && ((size_t)(endp - b) < len)) { unsigned long multiplier = NS_PER_SEC; real.tv_nsec = 0; - while (isdigit(*++endp) && (multiplier /= 10)) { + len -= endp - b; + while (--len && isdigit(*++endp) && (multiplier /= 10)) { real.tv_nsec += (*endp - '0') * multiplier; } if (reverse) { @@ -338,8 +380,8 @@ void LogKlog::sniffTime(log_time &now, const char **buf, bool reverse) { } } -pid_t LogKlog::sniffPid(const char *cp) { - while (*cp) { +pid_t LogKlog::sniffPid(const char *cp, size_t len) { + while (len) { // Mediatek kernels with modified printk if (*cp == '[') { int pid = 0; @@ -350,20 +392,21 @@ pid_t LogKlog::sniffPid(const char *cp) { break; // Only the first one } ++cp; + --len; } return 0; } // kernel log prefix, convert to a kernel log priority number -static int parseKernelPrio(const char **buf) { +static int parseKernelPrio(const char **buf, size_t len) { int pri = LOG_USER | LOG_INFO; const char *cp = *buf; - if (*cp == '<') { + if (len && (*cp == '<')) { pri = 0; - while(isdigit(*++cp)) { + while(--len && isdigit(*++cp)) { pri = (pri * 10) + *cp - '0'; } - if (*cp == '>') { + if (len && (*cp == '>')) { ++cp; } else { cp = *buf; @@ -376,15 +419,15 @@ static int parseKernelPrio(const char **buf) { // 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, suspendStr); +void LogKlog::synchronize(const char *buf, size_t len) { + const char *cp = strnstr(buf, len, suspendStr); if (!cp) { - cp = strstr(buf, resumeStr); + cp = strnstr(buf, len, resumeStr); if (!cp) { return; } } else { - const char *rp = strstr(buf, resumeStr); + const char *rp = strnstr(buf, len, resumeStr); if (rp && (rp < cp)) { cp = rp; } @@ -396,12 +439,12 @@ void LogKlog::synchronize(const char *buf) { if (*cp == '\n') { ++cp; } - parseKernelPrio(&cp); + parseKernelPrio(&cp, len - (cp - buf)); log_time now; - sniffTime(now, &cp, true); + sniffTime(now, &cp, len - (cp - buf), true); - char *suspended = strstr(buf, suspendedStr); + const char *suspended = strnstr(buf, len, suspendedStr); if (!suspended || (suspended > cp)) { return; } @@ -413,9 +456,9 @@ void LogKlog::synchronize(const char *buf) { if (*cp == '\n') { ++cp; } - parseKernelPrio(&cp); + parseKernelPrio(&cp, len - (cp - buf)); - sniffTime(now, &cp, true); + sniffTime(now, &cp, len - (cp - buf), true); } // Convert kernel log priority number into an Android Logger priority number @@ -491,19 +534,20 @@ static const char *strnrchr(const char *s, size_t len, char c) { // logd.klogd: // return -1 if message logd.klogd: // -int LogKlog::log(const char *buf) { - if (auditd && strstr(buf, " audit(")) { +int LogKlog::log(const char *buf, size_t len) { + if (auditd && strnstr(buf, len, " audit(")) { return 0; } - int pri = parseKernelPrio(&buf); + const char *p = buf; + int pri = parseKernelPrio(&p, len); log_time now; - sniffTime(now, &buf, false); + sniffTime(now, &p, len - (p - buf), false); // sniff for start marker const char klogd_message[] = "logd.klogd: "; - const char *start = strstr(buf, klogd_message); + const char *start = strnstr(p, len - (p - buf), klogd_message); if (start) { uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10); if (sig == signature.nsec()) { @@ -522,7 +566,7 @@ int LogKlog::log(const char *buf) { } // Parse pid, tid and uid - const pid_t pid = sniffPid(buf); + const pid_t pid = sniffPid(p, len - (p - buf)); const pid_t tid = pid; const uid_t uid = pid ? logbuf->pidToUid(pid) : 0; @@ -530,40 +574,43 @@ int LogKlog::log(const char *buf) { // 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; + while ((isspace(*p) || !*p) && (p < &buf[len])) { + ++p; } - if (!*buf) { + if (p >= &buf[len]) { // timestamp, no content return 0; } - start = buf; + start = p; const char *tag = ""; const char *etag = tag; - if (!isspace(*buf)) { + size_t taglen = len - (p - buf); + if (!isspace(*p) && *p) { const char *bt, *et, *cp; - bt = buf; - if (!strncmp(buf, "[INFO]", 6)) { + bt = p; + if (!strncmp(p, "[INFO]", 6)) { // [