From 5b1a538fc8c0d389071e737e527066de7c1d4735 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 3 Aug 2016 14:20:41 -0700 Subject: [PATCH 1/6] logcat: switch to android::base::StringPrintf asprintf should be replaced with StringPrintf, solves a memory leak issue because of exiting scope. Bug: 30591615 Change-Id: I88644cc27946ba4f25d4539420199c6f40df1bfa --- logcat/logcat.cpp | 32 +++++++++++++++----------------- 1 file changed, 15 insertions(+), 17 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index 5bac7172f..04efd68e0 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -26,6 +26,7 @@ #include #include +#include #include #include #include @@ -109,29 +110,27 @@ static void rotateLogs() (g_maxRotatedLogs > 0) ? (int) (floor(log10(g_maxRotatedLogs) + 1)) : 0; for (int i = g_maxRotatedLogs ; i > 0 ; i--) { - char *file0, *file1; - - asprintf(&file1, "%s.%.*d", g_outputFileName, maxRotationCountDigits, i); + std::string file1 = android::base::StringPrintf( + "%s.%.*d", g_outputFileName, maxRotationCountDigits, i); + std::string file0; if (i - 1 == 0) { - asprintf(&file0, "%s", g_outputFileName); + file0 = android::base::StringPrintf("%s", g_outputFileName); } else { - asprintf(&file0, "%s.%.*d", g_outputFileName, maxRotationCountDigits, i - 1); + file0 = android::base::StringPrintf( + "%s.%.*d", g_outputFileName, maxRotationCountDigits, i - 1); } - if (!file0 || !file1) { + if ((file0.length() == 0) || (file1.length() == 0)) { perror("while rotating log files"); break; } - err = rename(file0, file1); + err = rename(file0.c_str(), file1.c_str()); if (err < 0 && errno != ENOENT) { perror("while rotating log files"); } - - free(file1); - free(file0); } g_outFD = openLogFile(g_outputFileName); @@ -1040,28 +1039,27 @@ int main(int argc, char **argv) (g_maxRotatedLogs > 0) ? (int) (floor(log10(g_maxRotatedLogs) + 1)) : 0; for (int i = g_maxRotatedLogs ; i >= 0 ; --i) { - char *file; + std::string file; if (i == 0) { - asprintf(&file, "%s", g_outputFileName); + file = android::base::StringPrintf("%s", g_outputFileName); } else { - asprintf(&file, "%s.%.*d", g_outputFileName, maxRotationCountDigits, i); + file = android::base::StringPrintf("%s.%.*d", + g_outputFileName, maxRotationCountDigits, i); } - if (!file) { + if (file.length() == 0) { perror("while clearing log files"); clearFail = clearFail ?: dev->device; break; } - err = unlink(file); + err = unlink(file.c_str()); if (err < 0 && errno != ENOENT && clearFail == NULL) { perror("while clearing log files"); clearFail = dev->device; } - - free(file); } } else if (android_logger_clear(dev->logger)) { clearFail = clearFail ?: dev->device; From 02687e75b0d17ef08ab834553ba2fa3699fba09e Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 3 Aug 2016 14:20:41 -0700 Subject: [PATCH 2/6] logcat: add --id= for -f option Clear file rotate content if id signature changes. This allows logcatd to detect change of property ro.build.id to reset the recorded data. The id is stored in the the -f filespec as .id. If the id file is missing or unreadable, do not clear. Allow an API where chmod 0 to the id file blocks this feature. Does not work for root. Add logcat.logrotate_id gTest. Bug: 30591615 Change-Id: I895749ca7c6d4af57ec57f058a29d8e3af2f8b27 --- logcat/logcat.cpp | 31 +++++++++++++--- logcat/tests/logcat_test.cpp | 70 ++++++++++++++++++++++++++++++++++++ 2 files changed, 97 insertions(+), 4 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index 04efd68e0..49943fe83 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -283,6 +283,8 @@ static void show_help(const char *cmd) " Rotate log every kbytes. Requires -f option\n" " -n , --rotate-count=\n" " Sets max number of rotated logs to , default 4\n" + " --id= If the signature id for logging to file changes, then clear\n" + " the fileset and continue\n" " -v , --format=\n" " Sets log print format verb and adverbs, where is:\n" " brief long process raw tag thread threadtime time\n" @@ -546,6 +548,7 @@ int main(int argc, char **argv) unsigned long setLogSize = 0; int getPruneList = 0; char *setPruneList = NULL; + char *setId = NULL; int printStatistics = 0; int mode = ANDROID_LOG_RDONLY; const char *forceFilters = NULL; @@ -573,6 +576,7 @@ int main(int argc, char **argv) int option_index = 0; // list of long-argument only strings for later comparison static const char pid_str[] = "pid"; + static const char id_str[] = "id"; static const char wrap_str[] = "wrap"; static const char print_str[] = "print"; static const struct option long_options[] = { @@ -587,6 +591,7 @@ int main(int argc, char **argv) { "grep", required_argument, NULL, 'e' }, // hidden and undocumented reserved alias for --max-count { "head", required_argument, NULL, 'm' }, + { id_str, required_argument, NULL, 0 }, { "last", no_argument, NULL, 'L' }, { "max-count", required_argument, NULL, 'm' }, { pid_str, required_argument, NULL, 0 }, @@ -612,7 +617,7 @@ int main(int argc, char **argv) switch (ret) { case 0: - // One of the long options + // only long options if (long_options[option_index].name == pid_str) { // ToDo: determine runtime PID_MAX? if (!getSizeTArg(optarg, &pid, 1)) { @@ -643,6 +648,10 @@ int main(int argc, char **argv) g_printItAnyways = true; break; } + if (long_options[option_index].name == id_str) { + setId = optarg && optarg[0] ? optarg : NULL; + break; + } break; case 's': @@ -967,7 +976,20 @@ int main(int argc, char **argv) logcat_panic(true, "-r requires -f as well\n"); } - setupOutput(); + if (setId != NULL) { + if (g_outputFileName == NULL) { + logcat_panic(true, "--id='%s' requires -f as well\n", setId); + } + + std::string file_name = android::base::StringPrintf("%s.id", g_outputFileName); + std::string file; + bool file_ok = android::base::ReadFileToString(file_name, &file); + android::base::WriteStringToFile(setId, file_name, + S_IRUSR | S_IWUSR, getuid(), getgid()); + if (!file_ok || (file.compare(setId) == 0)) { + setId = NULL; + } + } if (hasSetLogFormat == 0) { const char* logFormat = getenv("ANDROID_PRINTF_LOG"); @@ -1033,7 +1055,7 @@ int main(int argc, char **argv) continue; } - if (clearLog) { + if (clearLog || setId) { if (g_outputFileName) { int maxRotationCountDigits = (g_maxRotatedLogs > 0) ? (int) (floor(log10(g_maxRotatedLogs) + 1)) : 0; @@ -1175,7 +1197,6 @@ int main(int argc, char **argv) return EXIT_SUCCESS; } - if (getLogSize) { return EXIT_SUCCESS; } @@ -1186,6 +1207,8 @@ int main(int argc, char **argv) return EXIT_SUCCESS; } + setupOutput(mode); + //LOG_EVENT_INT(10, 12345); //LOG_EVENT_LONG(11, 0x1122334455667788LL); //LOG_EVENT_STRING(0, "whassup, doc?"); diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp index 0043d1bc0..3daee134e 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -20,6 +20,7 @@ #include #include #include +#include #include #include @@ -848,6 +849,75 @@ TEST(logcat, logrotate_clear) { EXPECT_FALSE(system(command)); } +static int logrotate_count_id(const char *logcat_cmd, const char *tmp_out_dir) { + + static const char log_filename[] = "log.txt"; + char command[strlen(tmp_out_dir) + strlen(logcat_cmd) + strlen(log_filename) + 32]; + + snprintf(command, sizeof(command), logcat_cmd, tmp_out_dir, log_filename); + + int ret; + EXPECT_FALSE((ret = system(command))); + if (ret) { + return -1; + } + std::unique_ptr dir(opendir(tmp_out_dir), closedir); + EXPECT_NE(nullptr, dir); + if (!dir) { + return -1; + } + struct dirent *entry; + int count = 0; + while ((entry = readdir(dir.get()))) { + if (strncmp(entry->d_name, log_filename, sizeof(log_filename) - 1)) { + continue; + } + ++count; + } + return count; +} + +TEST(logcat, logrotate_id) { + static const char logcat_cmd[] = "logcat -b all -d -f %s/%s -n 32 -r 1 --id=test"; + static const char logcat_short_cmd[] = "logcat -b all -t 10 -f %s/%s -n 32 -r 1 --id=test"; + static const char tmp_out_dir_form[] = "/data/local/tmp/logcat.logrotate.XXXXXX"; + static const char log_filename[] = "log.txt"; + char tmp_out_dir[strlen(tmp_out_dir_form) + 1]; + ASSERT_TRUE(NULL != mkdtemp(strcpy(tmp_out_dir, tmp_out_dir_form))); + + EXPECT_EQ(34, logrotate_count_id(logcat_cmd, tmp_out_dir)); + EXPECT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); + + char id_file[strlen(tmp_out_dir_form) + strlen(log_filename) + 5]; + snprintf(id_file, sizeof(id_file), "%s/%s.id", tmp_out_dir, log_filename); + if (getuid() != 0) { + chmod(id_file, 0); + EXPECT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); + } + unlink(id_file); + EXPECT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); + + FILE *fp = fopen(id_file, "w"); + if (fp) { + fprintf(fp, "not_a_test"); + fclose(fp); + } + if (getuid() != 0) { + chmod(id_file, 0); // API to preserve content even with signature change + ASSERT_EQ(34, logrotate_count_id(logcat_short_cmd, tmp_out_dir)); + chmod(id_file, 0600); + } + + int new_signature; + EXPECT_LE(2, (new_signature = logrotate_count_id(logcat_short_cmd, tmp_out_dir))); + EXPECT_GT(34, new_signature); + + static const char cleanup_cmd[] = "rm -rf %s"; + char command[strlen(cleanup_cmd) + strlen(tmp_out_dir_form)]; + snprintf(command, sizeof(command), cleanup_cmd, tmp_out_dir); + EXPECT_FALSE(system(command)); +} + TEST(logcat, logrotate_nodir) { // expect logcat to error out on writing content and exit(1) for nodir EXPECT_EQ(W_EXITCODE(1, 0), From 2e5b71873c2e64ff7fd7092ea653e85b6fcea31b Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 3 Aug 2016 15:13:51 -0700 Subject: [PATCH 3/6] logcatd: fix up logpersist.cat to filter out signature file Simple filter for no suffix, or a numerical suffix. toybox grep did not handle a more robust regex, so we opted for kiss in order to remove the .id suffix from consideration. Bug: 30591615 Change-Id: I5b1c929d3e69c1ae39af95ae44a69f7b55e969ed --- logcat/logpersist | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/logcat/logpersist b/logcat/logpersist index 74d99fc7d..c09b6b212 100755 --- a/logcat/logpersist +++ b/logcat/logpersist @@ -17,8 +17,9 @@ true) ;; ;; esac +log_uid=logd log_tag_property=persist.log.tag -data=/data/misc/logd +data=/data/misc/logd/logcat service=logcatd size_default=256 buffer_default=all @@ -74,11 +75,12 @@ case ${progname} in if [ -n "${size}${buffer}" -o "true" = "${clear}" ]; then echo WARNING: Can not use --clear, --size or --buffer with ${progname%.*}.cat >&2 fi - su logd ls "${data}" | + su ${log_uid} ls "${data%/*}" | tr -d '\r' | sort -ru | - sed "s#^#${data}/#" | - su logd xargs cat + sed "s#^#${data%/*}/#" | + grep "${data}[.]*[0-9]*\$" | + su ${log_uid} xargs cat ;; *.start) current_buffer="`getprop ${property#persist.}.buffer`" @@ -139,7 +141,7 @@ case ${progname} in sleep 1 getprop ${property#persist.} # also generate an error return code if not found running - pgrep -u ${data##*/} ${service%d} + pgrep -u ${log_uid} ${service%d} ;; *.stop) if [ -n "${size}${buffer}" ]; then From 9b35df6517c9fbd1409e1a7ee0d2e021646fd38c Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 3 Aug 2016 15:17:06 -0700 Subject: [PATCH 4/6] logcatd: Add --id=${ro.build.id} If a new build lands, this will automatically clear out old logs in /data/misc/logd/ that may no longer be relevant. Bug: 30591615 Change-Id: Iecf61bb2a4928ce4b2e8cc6a3b122b7ae598d268 --- logcat/logcatd.rc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/logcat/logcatd.rc b/logcat/logcatd.rc index ce1a45181..1da1942ed 100644 --- a/logcat/logcatd.rc +++ b/logcat/logcatd.rc @@ -35,7 +35,7 @@ on property:logd.logpersistd.enable=true && property:logd.logpersistd=logcatd # all exec/services are called with umask(077), so no gain beyond 0700 mkdir /data/misc/logd 0700 logd log # logd for write to /data/misc/logd, log group for read from pstore (-L) - exec - logd log -- /system/bin/logcat -L -b ${logd.logpersistd.buffer:-all} -v threadtime -v usec -v printable -D -f /data/misc/logd/logcat -r 1024 -n ${logd.logpersistd.size:-256} + exec - logd log -- /system/bin/logcat -L -b ${logd.logpersistd.buffer:-all} -v threadtime -v usec -v printable -D -f /data/misc/logd/logcat -r 1024 -n ${logd.logpersistd.size:-256} --id=${ro.build.id} start logcatd # stop logcatd service and clear data @@ -56,7 +56,7 @@ on property:logd.logpersistd.enable=false stop logcatd # logcatd service -service logcatd /system/bin/logcat -b ${logd.logpersistd.buffer:-all} -v threadtime -v usec -v printable -D -f /data/misc/logd/logcat -r 1024 -n ${logd.logpersistd.size:-256} +service logcatd /system/bin/logcat -b ${logd.logpersistd.buffer:-all} -v threadtime -v usec -v printable -D -f /data/misc/logd/logcat -r 1024 -n ${logd.logpersistd.size:-256} --id=${ro.build.id} class late_start disabled # logd for write to /data/misc/logd, log group for read from log daemon From 31961061d5c483596616afaa69b33f77fea5ff97 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 4 Aug 2016 07:43:46 -0700 Subject: [PATCH 5/6] logcat: lastLogTime only two most recent files Scaling issues if -f logrotation is specified and there are a lot of log files to process in lastLogTime, focus on only the last two log files. This will cover the situation where we have recently rotated the logs and the last file is missing or empty. This also alters monotonic processing as well as it used to focus on only the last file; the danger being doubled now if the pair covers more than one reboot when filling in missing content with logcat -L. Problem was always there with one log file, but now we handle if rotation happened recently. A fair tradeoff for KISS. Bug: 30630936 Bug: 30612424 Bug: 28788401 Change-Id: I1c13b94e88f5edc08ecef52d407e296874ca5807 --- logcat/logcat.cpp | 20 +++++++------------- 1 file changed, 7 insertions(+), 13 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index 49943fe83..b761dd35f 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -444,7 +444,7 @@ static char *parseTime(log_time &t, const char *cp) { return t.strptime(cp, "%s.%q"); } -// Find last logged line in gestalt of all matching existing output files +// Find last logged line in , or .1 static log_time lastLogTime(char *outputFileName) { log_time retval(log_time::EPOCH); if (!outputFileName) { @@ -469,24 +469,18 @@ static log_time lastLogTime(char *outputFileName) { return retval; } - clockid_t clock_type = android_log_clockid(); - log_time now(clock_type); - bool monotonic = clock_type == CLOCK_MONOTONIC; + log_time now(android_log_clockid()); size_t len = strlen(file); log_time modulo(0, NS_PER_SEC); struct dirent *dp; while ((dp = readdir(dir.get())) != NULL) { - if ((dp->d_type != DT_REG) - // If we are using realtime, check all files that match the - // basename for latest time. If we are using monotonic time - // then only check the main file because time cycles on - // every reboot. - || strncmp(dp->d_name, file, len + monotonic) - || (dp->d_name[len] - && ((dp->d_name[len] != '.') - || !isdigit(dp->d_name[len+1])))) { + if ((dp->d_type != DT_REG) || + (strncmp(dp->d_name, file, len) != 0) || + (dp->d_name[len] && + ((dp->d_name[len] != '.') || + (strtoll(dp->d_name + 1, NULL, 10) != 1)))) { continue; } From ad5e411608a503a6a27c1e0515e1a0272c320bf2 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Thu, 4 Aug 2016 07:53:52 -0700 Subject: [PATCH 6/6] logcat: -d, -t or -L, along with -f, do not background Specifically logcatd with exec logcat -L needs to be foreground process cgroup as it is spawned and can block init progress. Makes sense generally to only set background cgroup when we are taking continuous content, and we are pushing that content to a set of logrotate files. Rename setupOutput to setupOutputAndSchedulingPolicy to more clearly indicate its purpose. Bug: 30630936 Bug: 30612424 Bug: 28788401 Change-Id: I628d590a42a53a6b448ecd0af53d6d1edf7bbb0e --- logcat/logcat.cpp | 52 ++++++++++++++++++++++++----------------------- 1 file changed, 27 insertions(+), 25 deletions(-) diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index b761dd35f..7e2bac779 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -230,13 +230,15 @@ static void maybePrintStart(log_device_t* dev, bool printDividers) { } } -static void setupOutput() -{ - +static void setupOutputAndSchedulingPolicy(bool blocking) { if (g_outputFileName == NULL) { g_outFD = STDOUT_FILENO; + return; + } - } else { + if (blocking) { + // Lower priority and set to batch scheduling if we are saving + // the logs into files and taking continuous content. if (set_sched_policy(0, SP_BACKGROUND) < 0) { fprintf(stderr, "failed to set background scheduling policy\n"); } @@ -250,26 +252,26 @@ static void setupOutput() if (setpriority(PRIO_PROCESS, 0, ANDROID_PRIORITY_BACKGROUND) < 0) { fprintf(stderr, "failed set to priority\n"); } - - g_outFD = openLogFile (g_outputFileName); - - if (g_outFD < 0) { - logcat_panic(false, "couldn't open output file"); - } - - struct stat statbuf; - if (fstat(g_outFD, &statbuf) == -1) { - close(g_outFD); - logcat_panic(false, "couldn't get output file stat\n"); - } - - if ((size_t) statbuf.st_size > SIZE_MAX || statbuf.st_size < 0) { - close(g_outFD); - logcat_panic(false, "invalid output file stat\n"); - } - - g_outByteCount = statbuf.st_size; } + + g_outFD = openLogFile (g_outputFileName); + + if (g_outFD < 0) { + logcat_panic(false, "couldn't open output file"); + } + + struct stat statbuf; + if (fstat(g_outFD, &statbuf) == -1) { + close(g_outFD); + logcat_panic(false, "couldn't get output file stat\n"); + } + + if ((size_t) statbuf.st_size > SIZE_MAX || statbuf.st_size < 0) { + close(g_outFD); + logcat_panic(false, "invalid output file stat\n"); + } + + g_outByteCount = statbuf.st_size; } static void show_help(const char *cmd) @@ -659,7 +661,7 @@ int main(int argc, char **argv) break; case 'L': - mode |= ANDROID_LOG_PSTORE; + mode |= ANDROID_LOG_RDONLY | ANDROID_LOG_PSTORE | ANDROID_LOG_NONBLOCK; break; case 'd': @@ -1201,7 +1203,7 @@ int main(int argc, char **argv) return EXIT_SUCCESS; } - setupOutput(mode); + setupOutputAndSchedulingPolicy((mode & ANDROID_LOG_NONBLOCK) == 0); //LOG_EVENT_INT(10, 12345); //LOG_EVENT_LONG(11, 0x1122334455667788LL);