aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorTao Bao <tbao@google.com>2015-09-10 15:32:24 -0700
committerSteve Kondik <steve@cyngn.com>2015-11-07 19:23:31 -0800
commit7e9b637c45449d2d4607c9f5ba681deb39c5b230 (patch)
treeb3dc4bc01ad44a3049211b798dc44de5b2949cca
parent9a8ffac5443031931b92b240f58dcb56d7ba95de (diff)
downloadbootable_recovery-7e9b637c45449d2d4607c9f5ba681deb39c5b230.zip
bootable_recovery-7e9b637c45449d2d4607c9f5ba681deb39c5b230.tar.gz
bootable_recovery-7e9b637c45449d2d4607c9f5ba681deb39c5b230.tar.bz2
recovery: Add timestamps in update logs.
Fork a logger process and send over the log lines through a pipe. Prepend a timestamp to each line for debugging purpose. Timestamps are relative to the start of the logger. Example lines with the change in this CL: [ 445.948393] Verifying update package... [ 446.279139] I:comment is 1738 bytes; signature 1720 bytes from end [ 449.463652] I:whole-file signature verified against RSA key 0 [ 449.463704] I:verify_file returned 0 Change-Id: I139d02ed8f2e944c1618c91d5cc43282efd50b99
-rw-r--r--Android.mk1
-rw-r--r--recovery.cpp114
2 files changed, 99 insertions, 16 deletions
diff --git a/Android.mk b/Android.mk
index 5c3b8d8..3db2656 100644
--- a/Android.mk
+++ b/Android.mk
@@ -81,6 +81,7 @@ LOCAL_STATIC_LIBRARIES := \
libselinux \
libm \
libc \
+ libc++_static \
libz
LOCAL_MODULE_PATH := $(TARGET_RECOVERY_ROOT_OUT)/sbin
diff --git a/recovery.cpp b/recovery.cpp
index 1c7fd5d..da962ba 100644
--- a/recovery.cpp
+++ b/recovery.cpp
@@ -31,6 +31,8 @@
#include <time.h>
#include <unistd.h>
+#include <chrono>
+
#include <base/file.h>
#include <base/stringprintf.h>
@@ -151,8 +153,7 @@ static const int MAX_ARG_LENGTH = 4096;
static const int MAX_ARGS = 100;
// open a given path, mounting partitions as necessary
-FILE*
-fopen_path(const char *path, const char *mode) {
+FILE* fopen_path(const char *path, const char *mode) {
if (ensure_path_mounted(path) != 0) {
LOGE("Can't mount %s\n", path);
return NULL;
@@ -166,23 +167,102 @@ fopen_path(const char *path, const char *mode) {
return fp;
}
+// close a file, log an error if the error indicator is set
+static void check_and_fclose(FILE *fp, const char *name) {
+ fflush(fp);
+ if (ferror(fp)) LOGE("Error in %s\n(%s)\n", name, strerror(errno));
+ fclose(fp);
+}
+
bool is_ro_debuggable() {
char value[PROPERTY_VALUE_MAX+1];
return (property_get("ro.debuggable", value, NULL) == 1 && value[0] == '1');
}
static void redirect_stdio(const char* filename) {
- // If these fail, there's not really anywhere to complain...
- freopen(filename, "a", stdout); setbuf(stdout, NULL);
- freopen(filename, "a", stderr); setbuf(stderr, NULL);
-}
+ int pipefd[2];
+ if (pipe(pipefd) == -1) {
+ LOGE("pipe failed: %s\n", strerror(errno));
-// close a file, log an error if the error indicator is set
-static void
-check_and_fclose(FILE *fp, const char *name) {
- fflush(fp);
- if (ferror(fp)) LOGE("Error in %s\n(%s)\n", name, strerror(errno));
- fclose(fp);
+ // Fall back to traditional logging mode without timestamps.
+ // If these fail, there's not really anywhere to complain...
+ freopen(filename, "a", stdout); setbuf(stdout, NULL);
+ freopen(filename, "a", stderr); setbuf(stderr, NULL);
+
+ return;
+ }
+
+ pid_t pid = fork();
+ if (pid == -1) {
+ LOGE("fork failed: %s\n", strerror(errno));
+
+ // Fall back to traditional logging mode without timestamps.
+ // If these fail, there's not really anywhere to complain...
+ freopen(filename, "a", stdout); setbuf(stdout, NULL);
+ freopen(filename, "a", stderr); setbuf(stderr, NULL);
+
+ return;
+ }
+
+ if (pid == 0) {
+ /// Close the unused write end.
+ close(pipefd[1]);
+
+ auto start = std::chrono::steady_clock::now();
+
+ // Child logger to actually write to the log file.
+ FILE* log_fp = fopen(filename, "a");
+ if (log_fp == nullptr) {
+ LOGE("fopen \"%s\" failed: %s\n", filename, strerror(errno));
+ close(pipefd[0]);
+ _exit(1);
+ }
+
+ FILE* pipe_fp = fdopen(pipefd[0], "r");
+ if (pipe_fp == nullptr) {
+ LOGE("fdopen failed: %s\n", strerror(errno));
+ check_and_fclose(log_fp, filename);
+ close(pipefd[0]);
+ _exit(1);
+ }
+
+ char* line = nullptr;
+ size_t len = 0;
+ while (getline(&line, &len, pipe_fp) != -1) {
+ auto now = std::chrono::steady_clock::now();
+ double duration = std::chrono::duration_cast<std::chrono::duration<double>>(
+ now - start).count();
+ if (line[0] == '\n') {
+ fprintf(log_fp, "[%12.6lf]\n", duration);
+ } else {
+ fprintf(log_fp, "[%12.6lf] %s", duration, line);
+ }
+ fflush(log_fp);
+ }
+
+ LOGE("getline failed: %s\n", strerror(errno));
+
+ free(line);
+ check_and_fclose(log_fp, filename);
+ close(pipefd[0]);
+ _exit(1);
+ } else {
+ // Redirect stdout/stderr to the logger process.
+ // Close the unused read end.
+ close(pipefd[0]);
+
+ setbuf(stdout, nullptr);
+ setbuf(stderr, nullptr);
+
+ if (dup2(pipefd[1], STDOUT_FILENO) == -1) {
+ LOGE("dup2 stdout failed: %s\n", strerror(errno));
+ }
+ if (dup2(pipefd[1], STDERR_FILENO) == -1) {
+ LOGE("dup2 stderr failed: %s\n", strerror(errno));
+ }
+
+ close(pipefd[1]);
+ }
}
// command line args come from, in decreasing precedence:
@@ -927,10 +1007,6 @@ ui_print(const char* format, ...) {
int
main(int argc, char **argv) {
- time_t start = time(NULL);
-
- redirect_stdio(TEMPORARY_LOG_FILE);
-
// If this binary is started with the single argument "--adbd",
// instead of being the normal recovery binary, it turns into kind
// of a stripped-down version of adbd that only supports the
@@ -943,6 +1019,12 @@ main(int argc, char **argv) {
return 0;
}
+ time_t start = time(NULL);
+
+ // redirect_stdio should be called only in non-sideload mode. Otherwise
+ // we may have two logger instances with different timestamps.
+ redirect_stdio(TEMPORARY_LOG_FILE);
+
printf("Starting recovery (pid %d) on %s", getpid(), ctime(&start));
load_volume_table();