From 2f824f59dc6556ba332c7244229f056819921431 Mon Sep 17 00:00:00 2001 From: topjohnwu Date: Mon, 1 Jun 2020 04:15:37 -0700 Subject: [PATCH] Better logging system Use C++ magic to strip out debug logs at compile time --- build.py | 2 +- native/jni/core/daemon.cpp | 16 +++--- native/jni/core/magisk.cpp | 10 ++-- native/jni/core/module.cpp | 5 -- native/jni/include/{flags.h => flags.hpp} | 0 native/jni/init/getinfo.cpp | 52 +++++++++++++++++--- native/jni/init/init.cpp | 48 +----------------- native/jni/magiskboot/main.cpp | 9 ++-- native/jni/magiskhide/magiskhide.cpp | 5 +- native/jni/magiskpolicy/magiskpolicy.cpp | 6 +-- native/jni/magiskpolicy/rules.cpp | 1 - native/jni/resetprop/resetprop.cpp | 3 +- native/jni/su/su.cpp | 4 +- native/jni/utils/include/logging.hpp | 33 ++++++------- native/jni/utils/logging.cpp | 60 +++++++++++++---------- native/jni/utils/xwrap.cpp | 2 +- 16 files changed, 118 insertions(+), 138 deletions(-) rename native/jni/include/{flags.h => flags.hpp} (100%) diff --git a/build.py b/build.py index a4dccf8a2..dd9e1c431 100755 --- a/build.py +++ b/build.py @@ -299,7 +299,7 @@ def build_binary(args): header('* Building binaries: ' + ' '.join(args.target)) - os.utime(op.join('native', 'jni', 'include', 'flags.h')) + os.utime(op.join('native', 'jni', 'include', 'flags.hpp')) # Basic flags global base_flags diff --git a/native/jni/core/daemon.cpp b/native/jni/core/daemon.cpp index 0e04e6244..80329a39e 100644 --- a/native/jni/core/daemon.cpp +++ b/native/jni/core/daemon.cpp @@ -13,7 +13,7 @@ #include #include #include -#include +#include using namespace std; @@ -129,16 +129,14 @@ shortcut: close(client); } +#define vlog __android_log_vprint + static void android_logging() { static constexpr char TAG[] = "Magisk"; -#ifdef MAGISK_DEBUG - log_cb.d = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_DEBUG, TAG, fmt, ap); }; -#else - log_cb.d = nop_log; -#endif - log_cb.i = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_INFO, TAG, fmt, ap); }; - log_cb.w = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_WARN, TAG, fmt, ap); }; - log_cb.e = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_ERROR, TAG, fmt, ap); }; + log_cb.d = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_DEBUG, TAG, fmt, ap); }; + log_cb.i = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_INFO, TAG, fmt, ap); }; + log_cb.w = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_WARN, TAG, fmt, ap); }; + log_cb.e = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_ERROR, TAG, fmt, ap); }; log_cb.ex = nop_ex; } diff --git a/native/jni/core/magisk.cpp b/native/jni/core/magisk.cpp index 269b435cd..7d7dc9896 100644 --- a/native/jni/core/magisk.cpp +++ b/native/jni/core/magisk.cpp @@ -1,21 +1,17 @@ #include -#include -#include -#include #include -#include #include #include #include #include -#include +#include -using namespace std::literals; +using namespace std; [[noreturn]] static void usage() { fprintf(stderr, -NAME_WITH_VER(Magisk) R"EOF( multi-call binary +R"EOF(Magisk - Multi-purpose Utility Usage: magisk [applet [arguments]...] or: magisk [options]... diff --git a/native/jni/core/module.cpp b/native/jni/core/module.cpp index e4bf3e4c3..b332b5865 100644 --- a/native/jni/core/module.cpp +++ b/native/jni/core/module.cpp @@ -7,15 +7,10 @@ #include #include #include -#include using namespace std; -#ifdef MAGISK_DEBUG #define VLOGI(tag, from, to) LOGI("%-8s: %s <- %s\n", tag, to, from) -#else -#define VLOGI(tag, from, to) LOGI("%-8s: %s\n", tag, to) -#endif #define TYPE_MIRROR (1 << 0) /* mount from mirror */ #define TYPE_INTER (1 << 1) /* intermediate node */ diff --git a/native/jni/include/flags.h b/native/jni/include/flags.hpp similarity index 100% rename from native/jni/include/flags.h rename to native/jni/include/flags.hpp diff --git a/native/jni/init/getinfo.cpp b/native/jni/init/getinfo.cpp index b4c31c27a..b34df144d 100644 --- a/native/jni/init/getinfo.cpp +++ b/native/jni/init/getinfo.cpp @@ -87,18 +87,58 @@ static bool check_key_combo() { return false; } -void load_kernel_info(cmdline *cmd) { - // Communicate with kernel using procfs and sysfs - xmkdir("/proc", 0755); - xmount("proc", "/proc", "proc", 0, nullptr); - xmkdir("/sys", 0755); - xmount("sysfs", "/sys", "sysfs", 0, nullptr); +static FILE *kmsg; +static char kmsg_buf[4096]; +static int vprintk(const char *fmt, va_list ap) { + vsnprintf(kmsg_buf + 12, sizeof(kmsg_buf) - 12, fmt, ap); + return fprintf(kmsg, "%s", kmsg_buf); +} +void setup_klog() { + // Shut down first 3 fds + int fd; + if (access("/dev/null", W_OK) == 0) { + fd = xopen("/dev/null", O_RDWR | O_CLOEXEC); + } else { + mknod("/null", S_IFCHR | 0666, makedev(1, 3)); + fd = xopen("/null", O_RDWR | O_CLOEXEC); + unlink("/null"); + } + xdup3(fd, STDIN_FILENO, O_CLOEXEC); + xdup3(fd, STDOUT_FILENO, O_CLOEXEC); + xdup3(fd, STDERR_FILENO, O_CLOEXEC); + if (fd > STDERR_FILENO) + close(fd); + + if (access("/dev/kmsg", W_OK) == 0) { + fd = xopen("/dev/kmsg", O_WRONLY | O_CLOEXEC); + } else { + mknod("/kmsg", S_IFCHR | 0666, makedev(1, 11)); + fd = xopen("/kmsg", O_WRONLY | O_CLOEXEC); + unlink("/kmsg"); + } + + kmsg = fdopen(fd, "w"); + setbuf(kmsg, nullptr); + log_cb.d = log_cb.i = log_cb.w = log_cb.e = vprintk; + log_cb.ex = nop_ex; + strcpy(kmsg_buf, "magiskinit: "); // Disable kmsg rate limiting if (FILE *rate = fopen("/proc/sys/kernel/printk_devkmsg", "w")) { fprintf(rate, "on\n"); fclose(rate); } +} + +void load_kernel_info(cmdline *cmd) { + // Get kernel data using procfs and sysfs + xmkdir("/proc", 0755); + xmount("proc", "/proc", "proc", 0, nullptr); + xmkdir("/sys", 0755); + xmount("sysfs", "/sys", "sysfs", 0, nullptr); + + // Log to kernel + setup_klog(); parse_cmdline([&](auto key, auto value) -> void { if (key == "androidboot.slot_suffix") { diff --git a/native/jni/init/init.cpp b/native/jni/init/init.cpp index a8466b21b..080131967 100644 --- a/native/jni/init/init.cpp +++ b/native/jni/init/init.cpp @@ -1,8 +1,6 @@ #include #include #include -#include -#include #include #include #include @@ -11,7 +9,6 @@ #include #include #include -#include #include "binaries.h" #ifdef USE_64BIT @@ -27,47 +24,6 @@ using namespace std; constexpr int (*init_applet_main[])(int, char *[]) = { magiskpolicy_main, magiskpolicy_main, nullptr }; -#ifdef MAGISK_DEBUG -static FILE *kmsg; -static char kmsg_buf[4096]; -static int vprintk(const char *fmt, va_list ap) { - vsnprintf(kmsg_buf + 12, sizeof(kmsg_buf) - 12, fmt, ap); - return fprintf(kmsg, "%s", kmsg_buf); -} -void setup_klog() { - // Shut down first 3 fds - int fd; - if (access("/dev/null", W_OK) == 0) { - fd = xopen("/dev/null", O_RDWR | O_CLOEXEC); - } else { - mknod("/null", S_IFCHR | 0666, makedev(1, 3)); - fd = xopen("/null", O_RDWR | O_CLOEXEC); - unlink("/null"); - } - xdup3(fd, STDIN_FILENO, O_CLOEXEC); - xdup3(fd, STDOUT_FILENO, O_CLOEXEC); - xdup3(fd, STDERR_FILENO, O_CLOEXEC); - if (fd > STDERR_FILENO) - close(fd); - - if (access("/dev/kmsg", W_OK) == 0) { - fd = xopen("/dev/kmsg", O_WRONLY | O_CLOEXEC); - } else { - mknod("/kmsg", S_IFCHR | 0666, makedev(1, 11)); - fd = xopen("/kmsg", O_WRONLY | O_CLOEXEC); - unlink("/kmsg"); - } - - kmsg = fdopen(fd, "w"); - setbuf(kmsg, nullptr); - log_cb.d = log_cb.i = log_cb.w = log_cb.e = vprintk; - log_cb.ex = nop_ex; - strcpy(kmsg_buf, "magiskinit: "); -} -#else -void setup_klog() {} -#endif - static bool unxz(int fd, const uint8_t *buf, size_t size) { uint8_t out[8192]; xz_crc32_init(); @@ -193,7 +149,7 @@ int main(int argc, char *argv[]) { return (*init_applet_main[i])(argc, argv); } -#ifdef MAGISK_DEBUG +#if 0 if (getenv("INIT_TEST") != nullptr) return test_main(argc, argv); #endif @@ -207,12 +163,12 @@ int main(int argc, char *argv[]) { if (getpid() != 1) return 1; - setup_klog(); BaseInit *init; cmdline cmd{}; if (argc > 1 && argv[1] == "selinux_setup"sv) { + setup_klog(); init = new SecondStageInit(argv); } else { // This will also mount /sys and /proc diff --git a/native/jni/magiskboot/main.cpp b/native/jni/magiskboot/main.cpp index 06256aa96..dc9a0c22d 100644 --- a/native/jni/magiskboot/main.cpp +++ b/native/jni/magiskboot/main.cpp @@ -1,13 +1,12 @@ -#include -#include -#include +#include +#include +#include #include #include #include #include #include -#include #include "magiskboot.hpp" #include "compress.hpp" @@ -16,7 +15,7 @@ using namespace std; static void usage(char *arg0) { fprintf(stderr, -NAME_WITH_VER(MagiskBoot) R"EOF( - Boot Image Modification Tool +R"EOF(MagiskBoot - Boot Image Modification Tool Usage: %s [args...] diff --git a/native/jni/magiskhide/magiskhide.cpp b/native/jni/magiskhide/magiskhide.cpp index 83fe0d960..7859ed8da 100644 --- a/native/jni/magiskhide/magiskhide.cpp +++ b/native/jni/magiskhide/magiskhide.cpp @@ -10,7 +10,6 @@ #include #include -#include #include "magiskhide.hpp" @@ -18,7 +17,7 @@ using namespace std::literals; [[noreturn]] static void usage(char *arg0) { fprintf(stderr, - NAME_WITH_VER(MagiskHide) "\n\n" + "MagiskHide - Hide Config CLI\n\n" "Usage: %s [action [arguments...] ]\n\n" "Actions:\n" " status Return the status of magiskhide\n" @@ -106,7 +105,7 @@ int magiskhide_main(int argc, char *argv[]) { execvp(argv[2], argv + 2); exit(1); } -#ifdef MAGISK_DEBUG +#if 0 else if (opt == "test"sv) test_proc_monitor(); #endif diff --git a/native/jni/magiskpolicy/magiskpolicy.cpp b/native/jni/magiskpolicy/magiskpolicy.cpp index 583424c04..45d441427 100644 --- a/native/jni/magiskpolicy/magiskpolicy.cpp +++ b/native/jni/magiskpolicy/magiskpolicy.cpp @@ -1,9 +1,5 @@ -#include -#include - #include #include -#include #include #include "sepolicy.hpp" @@ -12,7 +8,7 @@ using namespace std::literals; [[noreturn]] static void usage(char *arg0) { fprintf(stderr, -NAME_WITH_VER(MagiskPolicy) R"EOF( +R"EOF(MagiskPolicy - Sepolicy Patch Tool Usage: %s [--options...] [policy statements...] diff --git a/native/jni/magiskpolicy/rules.cpp b/native/jni/magiskpolicy/rules.cpp index 7db415aed..e7d6b9bf6 100644 --- a/native/jni/magiskpolicy/rules.cpp +++ b/native/jni/magiskpolicy/rules.cpp @@ -1,7 +1,6 @@ #include #include -#include #include #include "sepolicy.hpp" diff --git a/native/jni/resetprop/resetprop.cpp b/native/jni/resetprop/resetprop.cpp index dbf55b5a7..3dad2198e 100644 --- a/native/jni/resetprop/resetprop.cpp +++ b/native/jni/resetprop/resetprop.cpp @@ -6,7 +6,6 @@ #include #include #include -#include #define _REALLY_INCLUDE_SYS__SYSTEM_PROPERTIES_H_ #include <_system_properties.h> @@ -22,7 +21,7 @@ static int (*system_property_set)(const char*, const char*); [[noreturn]] static void usage(char* arg0) { fprintf(stderr, -NAME_WITH_VER(resetprop) R"EOF(" - System Props Modification Tool +R"EOF("resetprop - System Props Modification Tool Usage: %s [flags] [options...] diff --git a/native/jni/su/su.cpp b/native/jni/su/su.cpp index bb43f5d6c..6769362b0 100644 --- a/native/jni/su/su.cpp +++ b/native/jni/su/su.cpp @@ -23,7 +23,7 @@ #include #include -#include +#include #include "su.hpp" #include "pts.hpp" @@ -34,7 +34,7 @@ static void usage(int status) { FILE *stream = (status == EXIT_SUCCESS) ? stdout : stderr; fprintf(stream, - NAME_WITH_VER(MagiskSU) "\n\n" + "MagiskSU\n\n" "Usage: su [options] [-] [user [argument...]]\n\n" "Options:\n" " -c, --command COMMAND pass COMMAND to the invoked shell\n" diff --git a/native/jni/utils/include/logging.hpp b/native/jni/utils/include/logging.hpp index 211c55db8..0e58b0513 100644 --- a/native/jni/utils/include/logging.hpp +++ b/native/jni/utils/include/logging.hpp @@ -1,17 +1,15 @@ #pragma once -#include -#include -#include +#include +#include +#include -__BEGIN_DECLS - -typedef enum { +enum { L_DEBUG, L_INFO, L_WARN, L_ERR -} log_type; +}; struct log_callback { int (*d)(const char* fmt, va_list ap); @@ -21,20 +19,19 @@ struct log_callback { void (*ex)(int code); }; -extern struct log_callback log_cb; +extern log_callback log_cb; -#define LOGD(...) log_handler(L_DEBUG, __VA_ARGS__) -#define LOGI(...) log_handler(L_INFO, __VA_ARGS__) -#define LOGW(...) log_handler(L_WARN, __VA_ARGS__) -#define LOGE(...) log_handler(L_ERR, __VA_ARGS__) -#define PLOGE(fmt, args...) LOGE(fmt " failed with %d: %s\n", ##args, errno, strerror(errno)) +#define LOGD(...) log_handler(__VA_ARGS__) +#define LOGI(...) log_handler(__VA_ARGS__) +#define LOGW(...) log_handler(__VA_ARGS__) +#define LOGE(...) log_handler(__VA_ARGS__) +#define PLOGE(fmt, args...) LOGE(fmt " failed with %d: %s\n", ##args, errno, std::strerror(errno)) -int nop_log(const char *fmt, va_list ap); -void nop_ex(int i); +int nop_log(const char *, va_list); +void nop_ex(int); void no_logging(); void cmdline_logging(); -int log_handler(log_type t, const char *fmt, ...); - -__END_DECLS +template +void log_handler(const char *fmt, ...) __printflike(1, 2); diff --git a/native/jni/utils/logging.cpp b/native/jni/utils/logging.cpp index be49ad1ce..34bd09c54 100644 --- a/native/jni/utils/logging.cpp +++ b/native/jni/utils/logging.cpp @@ -1,15 +1,16 @@ -#include -#include +#include +#include #include +#include -int nop_log(const char *fmt, va_list ap) { - return 0; -} +using namespace std; -void nop_ex(int i) {} +int nop_log(const char *, va_list) { return 0; } -struct log_callback log_cb = { +void nop_ex(int) {} + +log_callback log_cb = { .d = nop_log, .i = nop_log, .w = nop_log, @@ -25,37 +26,42 @@ void no_logging() { log_cb.ex = nop_ex; } -static int vprinte(const char *fmt, va_list ap) { +static int vprintfe(const char *fmt, va_list ap) { return vfprintf(stderr, fmt, ap); } void cmdline_logging() { - log_cb.d = vprinte; + log_cb.d = vprintfe; log_cb.i = vprintf; - log_cb.w = vprinte; - log_cb.e = vprinte; + log_cb.w = vprintfe; + log_cb.e = vprintfe; log_cb.ex = exit; } -int log_handler(log_type t, const char *fmt, ...) { +template +void log_handler(const char *fmt, ...) { va_list argv; - int ret = 0; va_start(argv, fmt); - switch (t) { - case L_DEBUG: - ret = log_cb.d(fmt, argv); - break; - case L_INFO: - ret = log_cb.i(fmt, argv); - break; - case L_WARN: - ret = log_cb.w(fmt, argv); - break; - case L_ERR: - ret = log_cb.e(fmt, argv); + if constexpr (type == L_DEBUG) { + log_cb.d(fmt, argv); + } else if constexpr (type == L_INFO) { + log_cb.i(fmt, argv); + } else if constexpr (type == L_WARN) { + log_cb.w(fmt, argv); + } else if constexpr (type == L_ERR) { + log_cb.e(fmt, argv); log_cb.ex(1); - break; } va_end(argv); - return ret; } + +template void log_handler(const char *fmt, ...); +template void log_handler(const char *fmt, ...); +template void log_handler(const char *fmt, ...); + +#ifdef MAGISK_DEBUG +template void log_handler(const char *fmt, ...); +#else +// Strip debug logging for release builds +template <> void log_handler(const char *fmt, ...) {} +#endif diff --git a/native/jni/utils/xwrap.cpp b/native/jni/utils/xwrap.cpp index 70d1c0a78..a78ed8e27 100644 --- a/native/jni/utils/xwrap.cpp +++ b/native/jni/utils/xwrap.cpp @@ -84,7 +84,7 @@ ssize_t xread(int fd, void *buf, size_t count) { ssize_t xxread(int fd, void *buf, size_t count) { int ret = read(fd, buf, count); if (count != ret) { - PLOGE("read (%d != %d)", count, ret); + PLOGE("read (%zu != %d)", count, ret); } return ret; }