From 6c0ba66f17552e21ceea0e9df3f6b1939510716a Mon Sep 17 00:00:00 2001 From: topjohnwu Date: Thu, 8 Jun 2017 03:20:49 +0800 Subject: [PATCH] Add excessive logging for debug mode --- jni/daemon/bootstages.c | 20 ++++++++++++++---- jni/daemon/daemon.c | 5 +---- jni/daemon/log_monitor.c | 40 ++++++++++++++++++----------------- jni/magisk.h | 1 + jni/magiskhide/proc_monitor.c | 6 +++--- jni/resetprop/resetprop.cpp | 1 + jni/utils/misc.c | 35 +++++++++++++++++------------- jni/utils/utils.h | 2 +- scripts/magisk_uninstaller.sh | 2 +- 9 files changed, 65 insertions(+), 47 deletions(-) diff --git a/jni/daemon/bootstages.c b/jni/daemon/bootstages.c index 6933adcbc..5c2391d3a 100644 --- a/jni/daemon/bootstages.c +++ b/jni/daemon/bootstages.c @@ -172,7 +172,7 @@ void exec_common_script(const char* stage) { continue; LOGI("%s.d: exec [%s]\n", stage, entry->d_name); char *const command[] = { "sh", buf2, NULL }; - int pid = run_command(NULL, "/system/bin/sh", command); + int pid = run_command(0, NULL, "/system/bin/sh", command); if (pid != -1) waitpid(pid, NULL, 0); } @@ -189,7 +189,7 @@ void exec_module_script(const char* stage) { continue; LOGI("%s: exec [%s.sh]\n", module, stage); char *const command[] = { "sh", buf, NULL }; - int pid = run_command(NULL, "/system/bin/sh", command); + int pid = run_command(0, NULL, "/system/bin/sh", command); if (pid != -1) waitpid(pid, NULL, 0); } @@ -458,6 +458,10 @@ static void unblock_boot_process() { void post_fs(int client) { // Error handler err_handler = unblock_boot_process; + + // Start log monitor + monitor_logs(); + LOGI("** post-fs mode running\n"); // ack write_int(client, 0); @@ -730,8 +734,8 @@ void late_start(int client) { "CLASSPATH=/system/framework/pm.jar " "/system/bin/app_process /system/bin " "com.android.commands.pm.Pm install -r " MANAGERAPK, NULL }; - int apk_res, pid; - pid = run_command(&apk_res, "/system/bin/sh", command); + int apk_res = 0, pid; + pid = run_command(1, &apk_res, "/system/bin/sh", command); waitpid(pid, NULL, 0); fdgets(buf, PATH_MAX, apk_res); close(apk_res); @@ -746,4 +750,12 @@ void late_start(int client) { free(buf); free(buf2); vec_deep_destroy(&module_list); + +#ifdef DEBUG + // Stop recording the boot logcat after every boot task is done + extern int debug_log_pid, debug_log_fd; + kill(debug_log_pid, SIGTERM); + waitpid(debug_log_pid, NULL, 0); + close(debug_log_fd); +#endif } diff --git a/jni/daemon/daemon.c b/jni/daemon/daemon.c index f3660c5dc..50deb4c62 100644 --- a/jni/daemon/daemon.c +++ b/jni/daemon/daemon.c @@ -162,9 +162,6 @@ void start_daemon(int client) { // It should stay intact under any circumstances err_handler = do_nothing; - // Start log monitor - monitor_logs(); - LOGI("Magisk v" xstr(MAGISK_VERSION) " daemon started\n"); // Unlock all blocks for rw @@ -174,7 +171,7 @@ void start_daemon(int client) { xmount(NULL, "/", NULL, MS_REMOUNT, NULL); create_links(NULL, "/sbin"); xchmod("/sbin", 0755); - xmkdir("/magisk", 0755); + mkdir("/magisk", 0755); xchmod("/magisk", 0755); xmount(NULL, "/", NULL, MS_REMOUNT | MS_RDONLY, NULL); diff --git a/jni/daemon/log_monitor.c b/jni/daemon/log_monitor.c index 4113af052..e7124c2f6 100644 --- a/jni/daemon/log_monitor.c +++ b/jni/daemon/log_monitor.c @@ -15,41 +15,43 @@ #include "utils.h" #include "daemon.h" +#ifdef DEBUG +int debug_log_pid, debug_log_fd; +#endif + static void *logger_thread(void *args) { // Setup error handler err_handler = exit_thread; - char *buffer = xmalloc(PATH_MAX); rename(LOGFILE, LASTLOG); - FILE *logfile = xfdopen(xopen(LOGFILE, O_WRONLY | O_CREAT | O_CLOEXEC | O_TRUNC, 0644), "w"); - // Disable buffering - setbuf(logfile, NULL); - int fd, log_pid; + int log_fd, log_pid; + + log_fd = xopen(LOGFILE, O_WRONLY | O_CREAT | O_CLOEXEC | O_TRUNC, 0644); while (1) { // Start logcat - char *const command[] = { "logcat", "-s", "Magisk", "-v", "time", NULL }; - log_pid = run_command(&fd, "/system/bin/logcat", command); - while (fdgets(buffer, PATH_MAX, fd)) { - fprintf(logfile, "%s", buffer); - } - - // For some reason it went here, clear buffer and restart - close(fd); - kill(log_pid, SIGTERM); + char *const command[] = { "logcat", "-s", "Magisk", "-v", "thread", NULL }; + log_pid = run_command(0, &log_fd, "/system/bin/logcat", command); waitpid(log_pid, NULL, 0); + // For some reason it went here, clear buffer and restart system("logcat -c"); } // Should never be here, but well... - fclose(logfile); - free(buffer); + close(log_fd); return NULL; } /* Start a new thread to monitor logcat and dump to logfile */ void monitor_logs() { - pthread_t log_monitor_thread; - xpthread_create(&log_monitor_thread, NULL, logger_thread, NULL); - pthread_detach(log_monitor_thread); + pthread_t thread; + xpthread_create(&thread, NULL, logger_thread, NULL); + pthread_detach(thread); + +#ifdef DEBUG + // Start debug logs in new process + debug_log_fd = xopen(DEBUG_LOG, O_WRONLY | O_CREAT | O_CLOEXEC | O_TRUNC, 0644); + char *const command[] = { "logcat", "-v", "brief", NULL }; + debug_log_pid = run_command(0, &debug_log_fd, "/system/bin/logcat", command); +#endif } diff --git a/jni/magisk.h b/jni/magisk.h index bf84c9914..02e4e46aa 100644 --- a/jni/magisk.h +++ b/jni/magisk.h @@ -26,6 +26,7 @@ #define LOGFILE "/cache/magisk.log" #define LASTLOG "/cache/last_magisk.log" +#define DEBUG_LOG "/data/magisk_debug.log" #define UNBLOCKFILE "/dev/.magisk.unblock" #define DISABLEFILE "/cache/.disable_magisk" #define UNINSTALLER "/cache/magisk_uninstaller.sh" diff --git a/jni/magiskhide/proc_monitor.c b/jni/magiskhide/proc_monitor.c index aa9c75810..7d8eac62b 100644 --- a/jni/magiskhide/proc_monitor.c +++ b/jni/magiskhide/proc_monitor.c @@ -19,7 +19,7 @@ static int zygote_num = 0; static char init_ns[32], zygote_ns[2][32]; -static int log_pid = 0, log_fd; +static int log_pid = 0, log_fd = 0; static char *buffer; static void read_namespace(const int pid, char* target, const size_t size) { @@ -40,7 +40,7 @@ static void quit_pthread(int sig) { kill(log_pid, SIGTERM); waitpid(log_pid, NULL, 0); close(log_fd); - log_pid = 0; + log_fd = log_pid = 0; } int kill = -1; // If process monitor dies, kill hide daemon too @@ -107,7 +107,7 @@ void proc_monitor() { // Monitor am_proc_start char *const command[] = { "logcat", "-b", "events", "-v", "raw", "-s", "am_proc_start", NULL }; - log_pid = run_command(&log_fd, "/system/bin/logcat", command); + log_pid = run_command(0, &log_fd, "/system/bin/logcat", command); while(fdgets(buffer, PATH_MAX, log_fd)) { int ret, comma = 0; diff --git a/jni/resetprop/resetprop.cpp b/jni/resetprop/resetprop.cpp index 613e5cbab..6c2b94aa3 100644 --- a/jni/resetprop/resetprop.cpp +++ b/jni/resetprop/resetprop.cpp @@ -138,6 +138,7 @@ static void read_prop_info(void* cookie, const char *name, const char *value, ui char *getprop(const char *name) { const prop_info *pi = __system_property_find2(name); if (pi == NULL) { + PRINT_D("resetprop: failed to get [%s]\n", name); return NULL; } char value[PROP_VALUE_MAX]; diff --git a/jni/utils/misc.c b/jni/utils/misc.c index a5c91bf29..034cdf6f1 100644 --- a/jni/utils/misc.c +++ b/jni/utils/misc.c @@ -217,29 +217,34 @@ void setup_sighandlers(void (*handler)(int)) { } } -int run_command(int *fd, const char *path, char *const argv[]) { - int sv[2]; +/* + fd == NULL -> Ignore output + *fd == 0 -> Open pipe and set *fd to the read end + *fd != 0 -> STDOUT (or STDERR) will be redirected to *fd +*/ +int run_command(int err, int *fd, const char *path, char *const argv[]) { + int pipefd[2], writeEnd = 0; if (fd) { - if (socketpair(AF_LOCAL, SOCK_STREAM, 0, sv) == -1) - return -1; - // We use sv[0], give them sv[1] for communication - if (fcntl(sv[1], F_SETFD, FD_CLOEXEC)) - PLOGE("fcntl FD_CLOEXEC"); - *fd = sv[1]; + if (*fd == 0) { + if (pipe(pipefd) == -1) + return -1; + writeEnd = pipefd[1]; + // Give the read end of the pipe + *fd = pipefd[0]; + } } int pid = fork(); if (pid != 0) { - if (fd) close(sv[0]); + if (writeEnd) close(writeEnd); return pid; } if (fd) { - close(sv[1]); - xdup2(sv[0], STDIN_FILENO); - xdup2(sv[0], STDOUT_FILENO); - xdup2(sv[0], STDERR_FILENO); + if (writeEnd == 0) writeEnd = *fd; + xdup2(writeEnd, STDOUT_FILENO); + if (err) xdup2(writeEnd, STDERR_FILENO); } execv(path, argv); @@ -426,8 +431,8 @@ int get_img_size(const char *img, int *used, int *total) { char buffer[PATH_MAX]; snprintf(buffer, sizeof(buffer), "e2fsck -n %s 2>/dev/null | tail -n 1", img); char *const command[] = { "sh", "-c", buffer, NULL }; - int pid, fd; - pid = run_command(&fd, "/system/bin/sh", command); + int pid, fd = 0; + pid = run_command(0, &fd, "/system/bin/sh", command); fdgets(buffer, sizeof(buffer), fd); close(fd); if (pid == -1) diff --git a/jni/utils/utils.h b/jni/utils/utils.h index 500540919..10f72919f 100644 --- a/jni/utils/utils.h +++ b/jni/utils/utils.h @@ -82,7 +82,7 @@ void ps_filter_proc_name(const char *filter, void (*func)(int)); int create_links(const char *bin, const char *path); void unlock_blocks(); void setup_sighandlers(void (*handler)(int)); -int run_command(int *fd, const char *path, char *const argv[]); +int run_command(int err, int *fd, const char *path, char *const argv[]); int mkdir_p(const char *pathname, mode_t mode); int bind_mount(const char *from, const char *to); int open_new(const char *filename); diff --git a/scripts/magisk_uninstaller.sh b/scripts/magisk_uninstaller.sh index eba918835..ebcc089e5 100644 --- a/scripts/magisk_uninstaller.sh +++ b/scripts/magisk_uninstaller.sh @@ -148,7 +148,7 @@ rm -f stock_boot.img ui_print_wrap "- Removing Magisk files" rm -rf /cache/magisk.log /cache/last_magisk.log /cache/magiskhide.log /cache/.disable_magisk \ /cache/magisk /cache/magisk_merge /cache/magisk_mount /cache/unblock /cache/magisk_uninstaller.sh \ - /data/Magisk.apk /data/magisk.apk /data/magisk.img /data/magisk_merge.img \ + /data/Magisk.apk /data/magisk.apk /data/magisk.img /data/magisk_merge.img /data/magisk_debug.log \ /data/busybox /data/magisk /data/custom_ramdisk_patch.sh 2>/dev/null $BOOTMODE && reboot