From f3555d9427425c2cba9600ceffb49305c440aa4a Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 27 May 2015 07:39:56 -0700 Subject: [PATCH 1/4] logcat: -f flag to continue On startup, check the current logging content, then grab logs from that time forward rather than restarting from the beginning. Add support for reading tail time down to the nano-second. Bonus, permits us to create a logcatd logpersist daemon Bug: 19608716 Change-Id: Iaab58de4c02b7f97c69de12cf954fedc2163059e --- liblog/log_time.cpp | 2 +- logcat/Android.mk | 2 +- logcat/logcat.cpp | 98 ++++++++++++++++++++++++++++++++++++++++++--- 3 files changed, 95 insertions(+), 7 deletions(-) diff --git a/liblog/log_time.cpp b/liblog/log_time.cpp index 50742df70..9d5ea0e96 100644 --- a/liblog/log_time.cpp +++ b/liblog/log_time.cpp @@ -22,7 +22,7 @@ #include -const char log_time::default_format[] = "%m-%d %H:%M:%S.%3q"; +const char log_time::default_format[] = "%m-%d %H:%M:%S.%q"; const timespec log_time::EPOCH = { 0, 0 }; // Add %#q for fractional seconds to standard strptime function diff --git a/logcat/Android.mk b/logcat/Android.mk index f46a4deb6..fd54915fd 100644 --- a/logcat/Android.mk +++ b/logcat/Android.mk @@ -5,7 +5,7 @@ include $(CLEAR_VARS) LOCAL_SRC_FILES:= logcat.cpp event.logtags -LOCAL_SHARED_LIBRARIES := liblog +LOCAL_SHARED_LIBRARIES := liblog libbase LOCAL_MODULE := logcat diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index 2c2d785ce..afcc20ae4 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -2,6 +2,7 @@ #include #include +#include #include #include #include @@ -15,8 +16,14 @@ #include #include #include +#include #include +#include +#include + +#include +#include #include #include #include @@ -231,7 +238,7 @@ static void show_help(const char *cmd) fprintf(stderr, "options include:\n" " -s Set default filter to silent.\n" " Like specifying filterspec '*:S'\n" - " -f Log to file. Default to stdout\n" + " -f Log to file. Default is stdout\n" " -r Rotate log every kbytes. Requires -f\n" " -n Sets max number of rotated logs to , default 4\n" " -v Sets the log print format, where is:\n\n" @@ -352,6 +359,86 @@ static void logcat_panic(bool showHelp, const char *fmt, ...) exit(EXIT_FAILURE); } +static const char g_defaultTimeFormat[] = "%m-%d %H:%M:%S.%q"; + +// Find last logged line in gestalt of all matching existing output files +static log_time lastLogTime(char *outputFileName) { + log_time retval(log_time::EPOCH); + if (!outputFileName) { + return retval; + } + + log_time now(CLOCK_REALTIME); + + std::string directory; + char *file = strrchr(outputFileName, '/'); + if (!file) { + directory = "."; + file = outputFileName; + } else { + *file = '\0'; + directory = outputFileName; + *file = '/'; + ++file; + } + size_t len = strlen(file); + log_time modulo(0, NS_PER_SEC); + std::unique_ptrdir(opendir(directory.c_str()), closedir); + struct dirent *dp; + while ((dp = readdir(dir.get())) != NULL) { + if ((dp->d_type != DT_REG) + || strncmp(dp->d_name, file, len) + || (dp->d_name[len] + && ((dp->d_name[len] != '.') + || !isdigit(dp->d_name[len+1])))) { + continue; + } + + std::string file_name = directory; + file_name += "/"; + file_name += dp->d_name; + std::string file; + if (!android::base::ReadFileToString(file_name, &file)) { + continue; + } + + bool found = false; + for (const auto& line : android::base::Split(file, "\n")) { + log_time t(log_time::EPOCH); + char *ep = t.strptime(line.c_str(), g_defaultTimeFormat); + if (!ep || (*ep != ' ')) { + continue; + } + // determine the time precision of the logs (eg: msec or usec) + for (unsigned long mod = 1UL; mod < modulo.tv_nsec; mod *= 10) { + if (t.tv_nsec % (mod * 10)) { + modulo.tv_nsec = mod; + break; + } + } + // We filter any times later than current as we may not have the + // year stored with each log entry. Also, since it is possible for + // entries to be recorded out of order (very rare) we select the + // maximum we find just in case. + if ((t < now) && (t > retval)) { + retval = t; + found = true; + } + } + // We count on the basename file to be the definitive end, so stop here. + if (!dp->d_name[len] && found) { + break; + } + } + if (retval == log_time::EPOCH) { + return retval; + } + // tail_time prints matching or higher, round up by the modulo to prevent + // a replay of the last entry we have just checked. + retval += modulo; + return retval; +} + } /* namespace android */ @@ -417,12 +504,11 @@ int main(int argc, char **argv) /* FALLTHRU */ case 'T': if (strspn(optarg, "0123456789") != strlen(optarg)) { - char *cp = tail_time.strptime(optarg, - log_time::default_format); + char *cp = tail_time.strptime(optarg, g_defaultTimeFormat); if (!cp) { logcat_panic(false, "-%c \"%s\" not in \"%s\" time format\n", - ret, optarg, log_time::default_format); + ret, optarg, g_defaultTimeFormat); } if (*cp) { char c = *cp; @@ -545,9 +631,11 @@ int main(int argc, char **argv) break; case 'f': + if ((tail_time == log_time::EPOCH) && (tail_lines != 0)) { + tail_time = lastLogTime(optarg); + } // redirect output to a file g_outputFileName = optarg; - break; case 'r': From 3ef730c57f88ac24b0d6b021e43fc344d602fe36 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 2 Jun 2015 07:57:16 -0700 Subject: [PATCH 2/4] logcat: -f run in background - if saving to file, set SP_BACKGROUND policy - if saving to file, set BATCH priority - sort include files Bug: 19608716 Change-Id: I00acb8b8db0d2ff9ff36c97f9e74604d31938376 --- logcat/Android.mk | 2 +- logcat/logcat.cpp | 27 +++++++++++++++++++-------- 2 files changed, 20 insertions(+), 9 deletions(-) diff --git a/logcat/Android.mk b/logcat/Android.mk index fd54915fd..7115f9ba9 100644 --- a/logcat/Android.mk +++ b/logcat/Android.mk @@ -5,7 +5,7 @@ include $(CLEAR_VARS) LOCAL_SRC_FILES:= logcat.cpp event.logtags -LOCAL_SHARED_LIBRARIES := liblog libbase +LOCAL_SHARED_LIBRARIES := liblog libbase libcutils LOCAL_MODULE := logcat diff --git a/logcat/logcat.cpp b/logcat/logcat.cpp index afcc20ae4..6d7740eaa 100644 --- a/logcat/logcat.cpp +++ b/logcat/logcat.cpp @@ -1,36 +1,38 @@ // Copyright 2006-2015 The Android Open Source Project +#include #include #include #include #include #include #include +#include +#include +#include #include #include -#include #include -#include -#include -#include #include #include #include #include -#include +#include +#include #include #include #include #include +#include #include +#include #include #include -#include #include +#include #include -#include #define DEFAULT_MAX_ROTATED_LOGS 4 @@ -209,7 +211,15 @@ static void setupOutput() g_outFD = STDOUT_FILENO; } else { - struct stat statbuf; + if (set_sched_policy(0, SP_BACKGROUND) < 0) { + fprintf(stderr, "failed to set background scheduling policy\n"); + } + + struct sched_param param; + memset(¶m, 0, sizeof(param)); + if (sched_setscheduler((pid_t) 0, SCHED_BATCH, ¶m) < 0) { + fprintf(stderr, "failed to set to batch scheduler\n"); + } g_outFD = openLogFile (g_outputFileName); @@ -217,6 +227,7 @@ static void setupOutput() 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"); From 17fff893c04971b519d25d52b07f51111353cba5 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 2 Jun 2015 11:11:02 -0700 Subject: [PATCH 3/4] init: change exec parsing to make SECLABEL optional Allow SECLABEL to be - to denote default Change-Id: I58cdc6c805dc6e50dc42b7e13e72d0eaf4864f11 --- init/init.cpp | 3 ++- init/init_parser.cpp | 3 ++- init/readme.txt | 2 +- 3 files changed, 5 insertions(+), 3 deletions(-) diff --git a/init/init.cpp b/init/init.cpp index 60fcf6463..250098536 100644 --- a/init/init.cpp +++ b/init/init.cpp @@ -380,7 +380,8 @@ void service_start(struct service *svc, const char *dynamic_args) if ((svc->flags & SVC_EXEC) != 0) { INFO("SVC_EXEC pid %d (uid %d gid %d+%zu context %s) started; waiting...\n", - svc->pid, svc->uid, svc->gid, svc->nr_supp_gids, svc->seclabel); + svc->pid, svc->uid, svc->gid, svc->nr_supp_gids, + svc->seclabel ? : "default"); waiting_for_exec = true; } diff --git a/init/init_parser.cpp b/init/init_parser.cpp index df049edeb..f975b6c0b 100644 --- a/init/init_parser.cpp +++ b/init/init_parser.cpp @@ -664,6 +664,7 @@ int action_queue_empty() service* make_exec_oneshot_service(int nargs, char** args) { // Parse the arguments: exec [SECLABEL [UID [GID]*] --] COMMAND ARGS... + // SECLABEL can be a - to denote default int command_arg = 1; for (int i = 1; i < nargs; ++i) { if (strcmp(args[i], "--") == 0) { @@ -689,7 +690,7 @@ service* make_exec_oneshot_service(int nargs, char** args) { return NULL; } - if (command_arg > 2) { + if ((command_arg > 2) && strcmp(args[1], "-")) { svc->seclabel = args[1]; } if (command_arg > 3) { diff --git a/init/readme.txt b/init/readme.txt index 6b9c42d3f..c2130416d 100644 --- a/init/readme.txt +++ b/init/readme.txt @@ -180,7 +180,7 @@ exec [ [ [ ]* ] ] -- [ ]* Fork and execute command with the given arguments. The command starts after "--" so that an optional security context, user, and supplementary groups can be provided. No other commands will be run until this one - finishes. + finishes. can be a - to denote default. export Set the environment variable equal to in the From 100658c303919d8f69c76f6f25eac376795712f0 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 26 May 2015 14:57:13 -0700 Subject: [PATCH 4/4] init.rc: logd: Add logpersistd (nee logcatd) - logpersistd is defined as a thread or process in the context of the logd domain. Here we define logpersistd as logcat -f in logd domain and call it logcatd to represent its service mechanics. - Use logcatd to manage content in /data/misc/logd/ directory. - Only turn on for persist.logd.logpersistd = logcatd. - Add logpersist.start, logpersist.stop and logpersist.cat debug class executables, thus only in the eng and userdebug builds. ToDo: Wish to add Developer Options menu to turn this feature on or off, complicated by the fact that user builds have no tools with access rights to /data/misc/logd. Bug: 19608716 Change-Id: I57ad757f121c473d04f9fabe9d4820a0eca06f31 --- logd/Android.mk | 11 +++++++++++ logd/README.property | 2 ++ logd/logpersist | 36 ++++++++++++++++++++++++++++++++++++ rootdir/init.rc | 14 ++++++++++++++ 4 files changed, 63 insertions(+) create mode 100755 logd/logpersist diff --git a/logd/Android.mk b/logd/Android.mk index 73da8dc61..615d03048 100644 --- a/logd/Android.mk +++ b/logd/Android.mk @@ -41,4 +41,15 @@ LOCAL_CFLAGS := -Werror $(event_flag) include $(BUILD_EXECUTABLE) +include $(CLEAR_VARS) + +LOCAL_MODULE := logpersist.start +LOCAL_MODULE_TAGS := debug +LOCAL_MODULE_CLASS := EXECUTABLES +LOCAL_MODULE_PATH := $(bin_dir) +LOCAL_SRC_FILES := logpersist +ALL_TOOLS := logpersist.start logpersist.stop logpersist.cat +LOCAL_POST_INSTALL_CMD := $(hide) $(foreach t,$(filter-out $(LOCAL_MODULE),$(ALL_TOOLS)),ln -sf $(LOCAL_MODULE) $(TARGET_OUT)/bin/$(t);) +include $(BUILD_PREBUILT) + include $(call first-makefiles-under,$(LOCAL_PATH)) diff --git a/logd/README.property b/logd/README.property index ad7d0cd3e..a472efde9 100644 --- a/logd/README.property +++ b/logd/README.property @@ -10,6 +10,8 @@ ro.config.low_ram bool false if true, logd.statistics & logd.klogd default false ro.build.type string if user, logd.statistics & logd.klogd default false +persist.logd.logpersistd string Enable logpersist daemon, "logcatd" + turns on logcat -f in logd context persist.logd.size number 256K default size of the buffer for all log ids at initial startup, at runtime use: logcat -b all -G diff --git a/logd/logpersist b/logd/logpersist new file mode 100755 index 000000000..215e1e2d9 --- /dev/null +++ b/logd/logpersist @@ -0,0 +1,36 @@ +#! /system/bin/sh +# logpersist cat start and stop handlers +data=/data/misc/logd +property=persist.logd.logpersistd +service=logcatd +progname="${0##*/}" +if [ X"${1}" = "-h" -o X"${1}" = X"--help" ]; then + echo "${progname%.*}.cat - dump current ${service%d} logs" + echo "${progname%.*}.start - start ${service} service" + echo "${progname%.*}.stop [--clear] - stop ${service} service" + exit 0 +fi +case ${progname} in +*.cat) + su 1036 ls "${data}" | + tr -d '\r' | + sort -ru | + sed "s#^#${data}/#" | + su 1036 xargs cat + ;; +*.start) + su 0 setprop ${property} ${service} + getprop ${property} + sleep 1 + ps -t | grep "${data##*/}.*${service%d}" + ;; +*.stop) + su 0 stop ${service} + su 0 setprop ${property} "" + [ X"${1}" != X"-c" -a X"${1}" != X"--clear" ] || + ( sleep 1 ; su 1036,9998 rm -rf "${data}" ) + ;; +*) + echo "Unexpected command ${0##*/} ${@}" >&2 + exit 1 +esac diff --git a/rootdir/init.rc b/rootdir/init.rc index 09660389a..1f421c5b7 100644 --- a/rootdir/init.rc +++ b/rootdir/init.rc @@ -649,3 +649,17 @@ service perfprofd /system/xbin/perfprofd class late_start user root oneshot + +on property:persist.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 all -v threadtime -v usec -v printable -D -f /data/misc/logd/logcat -r 64 -n 256 + start logcatd + +service logcatd /system/bin/logcat -b all -v threadtime -v usec -v printable -D -f /data/misc/logd/logcat -r 64 -n 256 + class late_start + disabled + # logd for write to /data/misc/logd, log group for read from log daemon + user logd + group log