From 70fd03d5fc7f7864730e4ccfe2db0f6e20d715a7 Mon Sep 17 00:00:00 2001 From: topjohnwu Date: Wed, 6 Jul 2022 01:16:08 -0700 Subject: [PATCH] Rearchitect logging --- native/jni/base/logging.cpp | 49 +++--------- native/jni/base/logging.hpp | 15 +--- native/jni/core/core.hpp | 1 - native/jni/core/logging.cpp | 12 --- native/jni/include/daemon.hpp | 1 - native/jni/init/getinfo.cpp | 12 ++- native/jni/resetprop/resetprop.cpp | 3 +- native/jni/sepolicy/rules.cpp | 5 +- native/jni/zygisk/entry.cpp | 6 -- native/rust/base/src/lib.rs | 10 +-- native/rust/base/src/logging.rs | 121 ++++++++++++++++++++--------- native/rust/core/src/lib.rs | 6 -- native/rust/core/src/logging.rs | 65 +++++++++++----- native/rust/init/src/logging.rs | 20 +++-- 14 files changed, 172 insertions(+), 154 deletions(-) diff --git a/native/jni/base/logging.cpp b/native/jni/base/logging.cpp index 94d7c0f38..067233d4d 100644 --- a/native/jni/base/logging.cpp +++ b/native/jni/base/logging.cpp @@ -11,23 +11,15 @@ using namespace std; -void nop_log(const char *, va_list) {} - -log_callback log_cb = { - .d = nop_log, - .i = nop_log, - .w = nop_log, - .e = nop_log, -}; -static bool EXIT_ON_ERROR = false; - static int fmt_and_log_with_rs(LogLevel level, const char *fmt, va_list ap) { char buf[4096]; int ret = vsnprintf(buf, sizeof(buf), fmt, ap); - log_with_rs(level, buf); + log_with_rs(level, rust::Str(buf, ret)); return ret; } +int (*cpp_logger)(LogLevel level, const char *fmt, va_list ap) = fmt_and_log_with_rs; + // Used to override external C library logging extern "C" int magisk_log_print(int prio, const char *tag, const char *fmt, ...) { LogLevel level; @@ -55,48 +47,29 @@ extern "C" int magisk_log_print(int prio, const char *tag, const char *fmt, ...) snprintf(fmt_buf + len, sizeof(fmt_buf) - len, ": %s", fmt); va_list argv; va_start(argv, fmt); - int ret = fmt_and_log_with_rs(level, fmt_buf, argv); + int ret = cpp_logger(level, fmt_buf, argv); va_end(argv); return ret; } -#define rlog(prio) [](auto fmt, auto ap) { fmt_and_log_with_rs(LogLevel::prio, fmt, ap); } -void forward_logging_to_rs() { - log_cb.d = rlog(Debug); - log_cb.i = rlog(Info); - log_cb.w = rlog(Warn); - log_cb.e = rlog(Error); -} - -void cmdline_logging() { - rust::cmdline_logging(); - forward_logging_to_rs(); - exit_on_error(true); -} - -void exit_on_error(bool b) { - rust::exit_on_error(b); - EXIT_ON_ERROR = b; -} - -#define LOG_BODY(prio) { \ +#define LOG_BODY(level) { \ va_list argv; \ va_start(argv, fmt); \ - log_cb.prio(fmt, argv); \ + cpp_logger(LogLevel::level, fmt, argv); \ va_end(argv); \ } // LTO will optimize out the NOP function #if MAGISK_DEBUG -void LOGD(const char *fmt, ...) { LOG_BODY(d) } +void LOGD(const char *fmt, ...) { LOG_BODY(Debug) } #else void LOGD(const char *fmt, ...) {} #endif -void LOGI(const char *fmt, ...) { LOG_BODY(i) } -void LOGW(const char *fmt, ...) { LOG_BODY(w) } -void LOGE(const char *fmt, ...) { LOG_BODY(e); if (EXIT_ON_ERROR) exit(EXIT_FAILURE); } +void LOGI(const char *fmt, ...) { LOG_BODY(Info) } +void LOGW(const char *fmt, ...) { LOG_BODY(Warn) } +void LOGE(const char *fmt, ...) { LOG_BODY(Error) } // Export raw symbol to fortify compat extern "C" void __vloge(const char* fmt, va_list ap) { - log_cb.e(fmt, ap); + cpp_logger(LogLevel::Error, fmt, ap); } diff --git a/native/jni/base/logging.hpp b/native/jni/base/logging.hpp index bd281b1f7..ac0a3dc4e 100644 --- a/native/jni/base/logging.hpp +++ b/native/jni/base/logging.hpp @@ -3,23 +3,12 @@ #include #include -struct log_callback { - void (*d)(const char* fmt, va_list ap); - void (*i)(const char* fmt, va_list ap); - void (*w)(const char* fmt, va_list ap); - void (*e)(const char* fmt, va_list ap); -}; +#include -extern log_callback log_cb; +extern int (*cpp_logger)(LogLevel level, const char *fmt, va_list ap); void LOGD(const char *fmt, ...) __printflike(1, 2); void LOGI(const char *fmt, ...) __printflike(1, 2); void LOGW(const char *fmt, ...) __printflike(1, 2); void LOGE(const char *fmt, ...) __printflike(1, 2); #define PLOGE(fmt, args...) LOGE(fmt " failed with %d: %s\n", ##args, errno, std::strerror(errno)) - -void nop_log(const char *, va_list); - -void forward_logging_to_rs(); -void cmdline_logging(); -void exit_on_error(bool b); diff --git a/native/jni/core/core.hpp b/native/jni/core/core.hpp index 78f417f6f..598d95339 100644 --- a/native/jni/core/core.hpp +++ b/native/jni/core/core.hpp @@ -20,7 +20,6 @@ void unlock_blocks(); void reboot(); void start_log_daemon(); void setup_logfile(bool reset); -void magisk_logging(); std::string read_certificate(int fd, int version = -1); // Module stuffs diff --git a/native/jni/core/logging.cpp b/native/jni/core/logging.cpp index 72be31680..a697a659c 100644 --- a/native/jni/core/logging.cpp +++ b/native/jni/core/logging.cpp @@ -149,18 +149,6 @@ void magisk_log_write(int prio, const char *msg, int len) { } } -void magisk_logging() { - rust::magisk_logging(); - forward_logging_to_rs(); - exit_on_error(false); -} - -void android_logging() { - rust::android_logging(); - forward_logging_to_rs(); - exit_on_error(false); -} - void start_log_daemon() { int fds[2]; if (pipe2(fds, O_CLOEXEC) == 0) { diff --git a/native/jni/include/daemon.hpp b/native/jni/include/daemon.hpp index da5c8cbd6..6c5b436e3 100644 --- a/native/jni/include/daemon.hpp +++ b/native/jni/include/daemon.hpp @@ -81,7 +81,6 @@ void exec_task(std::function &&task); // Logging extern std::atomic logd_fd; -void android_logging(); extern "C" void magisk_log_write(int prio, const char *msg, int len); // Daemon handlers diff --git a/native/jni/init/getinfo.cpp b/native/jni/init/getinfo.cpp index 7e85dd8ae..1333df9b3 100644 --- a/native/jni/init/getinfo.cpp +++ b/native/jni/init/getinfo.cpp @@ -121,6 +121,15 @@ static FILE *kmsg; extern "C" void klog_write(const char *msg, int len) { fprintf(kmsg, "%.*s", len, msg); } + +static int klog_with_rs(LogLevel level, const char *fmt, va_list ap) { + char buf[4096]; + strlcpy(buf, "magiskinit: ", sizeof(buf)); + int len = vsnprintf(buf + 12, sizeof(buf) - 12, fmt, ap) + 12; + log_with_rs(level, rust::Str(buf, len)); + return len; +} + void setup_klog() { // Shut down first 3 fds int fd; @@ -148,8 +157,7 @@ void setup_klog() { kmsg = fdopen(fd, "w"); setbuf(kmsg, nullptr); rust::setup_klog(); - forward_logging_to_rs(); - exit_on_error(false); + cpp_logger = klog_with_rs; // Disable kmsg rate limiting if (FILE *rate = fopen("/proc/sys/kernel/printk_devkmsg", "w")) { diff --git a/native/jni/resetprop/resetprop.cpp b/native/jni/resetprop/resetprop.cpp index bc3b0e194..415e10c03 100644 --- a/native/jni/resetprop/resetprop.cpp +++ b/native/jni/resetprop/resetprop.cpp @@ -337,8 +337,7 @@ int resetprop_main(int argc, char *argv[]) { ++argv; } - if (!verbose) - log_cb.d = nop_log; + set_log_level_state(LogLevel::Debug, verbose); switch (argc) { case 0: diff --git a/native/jni/sepolicy/rules.cpp b/native/jni/sepolicy/rules.cpp index 775e3ca79..2bc300a7e 100644 --- a/native/jni/sepolicy/rules.cpp +++ b/native/jni/sepolicy/rules.cpp @@ -6,8 +6,7 @@ using namespace std; void sepolicy::magisk_rules() { // Temp suppress warnings - auto bak = log_cb.w; - log_cb.w = nop_log; + set_log_level_state(LogLevel::Warn, false); // This indicates API 26+ bool new_rules = exists("untrusted_app_25"); @@ -196,5 +195,5 @@ void sepolicy::magisk_rules() { impl->strip_dontaudit(); #endif - log_cb.w = bak; + set_log_level_state(LogLevel::Warn, true); } diff --git a/native/jni/zygisk/entry.cpp b/native/jni/zygisk/entry.cpp index 8977c6b91..b156bb315 100644 --- a/native/jni/zygisk/entry.cpp +++ b/native/jni/zygisk/entry.cpp @@ -17,12 +17,6 @@ using namespace std; void *self_handle = nullptr; -static void zygisk_logging() { - rust::zygisk_logging(); - forward_logging_to_rs(); - exit_on_error(false); -} - // Make sure /proc/self/environ is sanitized // Filter env and reset MM_ENV_END static void sanitize_environ() { diff --git a/native/rust/base/src/lib.rs b/native/rust/base/src/lib.rs index 98d4d5450..445277458 100644 --- a/native/rust/base/src/lib.rs +++ b/native/rust/base/src/lib.rs @@ -8,6 +8,7 @@ mod misc; #[cxx::bridge] pub mod ffi { + #[derive(Copy, Clone)] pub enum LogLevel { Error, Warn, @@ -17,13 +18,8 @@ pub mod ffi { extern "Rust" { fn log_with_rs(level: LogLevel, msg: &str); - } -} - -#[cxx::bridge(namespace = "rust")] -pub mod ffi2 { - extern "Rust" { - fn cmdline_logging(); fn exit_on_error(b: bool); + fn set_log_level_state(level: LogLevel, enabled: bool); + fn cmdline_logging(); } } diff --git a/native/rust/base/src/logging.rs b/native/rust/base/src/logging.rs index e031e542a..0c6dbfaf9 100644 --- a/native/rust/base/src/logging.rs +++ b/native/rust/base/src/logging.rs @@ -1,64 +1,113 @@ use std::fmt::Arguments; +use std::io::{stderr, stdout, Write}; use std::process::exit; use crate::ffi::LogLevel; +// Ugly hack to avoid using enum +#[allow(non_snake_case, non_upper_case_globals)] +mod LogFlag { + pub const DisableError: u32 = 0x1; + pub const DisableWarn: u32 = 0x2; + pub const DisableInfo: u32 = 0x4; + pub const DisableDebug: u32 = 0x8; + pub const ExitOnError: u32 = 0x10; +} + // We don't need to care about thread safety, because all // logger changes will only happen on the main thread. pub static mut LOGGER: Logger = Logger { - d: nop_log, - i: nop_log, - w: nop_log, - e: nop_log, + fmt: |_, _| {}, + write: |_, _| {}, + flags: 0, }; -static mut EXIT_ON_ERROR: bool = false; #[derive(Copy, Clone)] pub struct Logger { - pub d: fn(args: Arguments), - pub i: fn(args: Arguments), - pub w: fn(args: Arguments), - pub e: fn(args: Arguments), -} - -pub fn nop_log(_: Arguments) {} - -pub fn log_with_rs(level: LogLevel, msg: &str) { - log_impl(level, format_args!("{}", msg)); + pub fmt: fn(level: LogLevel, args: Arguments), + pub write: fn(level: LogLevel, msg: &[u8]), + pub flags: u32, } pub fn exit_on_error(b: bool) { - unsafe { EXIT_ON_ERROR = b; } + unsafe { + if b { + LOGGER.flags |= LogFlag::ExitOnError; + } else { + LOGGER.flags &= !LogFlag::ExitOnError; + } + } } -pub fn cmdline_logging() { - fn print(args: Arguments) { print!("{}", args); } - fn eprint(args: Arguments) { eprint!("{}", args); } +impl LogLevel { + fn to_disable_flag(&self) -> u32 { + match *self { + LogLevel::Error => LogFlag::DisableError, + LogLevel::Warn => LogFlag::DisableWarn, + LogLevel::Info => LogFlag::DisableInfo, + LogLevel::Debug => LogFlag::DisableDebug, + _ => 0 + } + } +} - let logger = Logger { - d: eprint, - i: print, - w: eprint, - e: eprint, - }; +pub fn set_log_level_state(level: LogLevel, enabled: bool) { + let flag = level.to_disable_flag(); unsafe { - LOGGER = logger; - EXIT_ON_ERROR = true; + if enabled { + LOGGER.flags &= !flag + } else { + LOGGER.flags |= flag + } + } +} + +pub fn log_with_rs(level: LogLevel, msg: &str) { + let logger = unsafe { LOGGER }; + if (logger.flags & level.to_disable_flag()) != 0 { + return; + } + (logger.write)(level, msg.as_bytes()); + if level == LogLevel::Error && (logger.flags & LogFlag::ExitOnError) != 0 { + exit(1); } } pub fn log_impl(level: LogLevel, args: Arguments) { let logger = unsafe { LOGGER }; - let aoe = unsafe { EXIT_ON_ERROR }; - match level { - LogLevel::Error => { - (logger.e)(args); - if aoe { exit(1); } + if (logger.flags & level.to_disable_flag()) != 0 { + return; + } + (logger.fmt)(level, args); + if level == LogLevel::Error && (logger.flags & LogFlag::ExitOnError) != 0 { + exit(1); + } +} + +pub fn cmdline_logging() { + fn print(level: LogLevel, args: Arguments) { + if level == LogLevel::Info { + print!("{}", args); + } else { + eprint!("{}", args); } - LogLevel::Warn => (logger.w)(args), - LogLevel::Info => (logger.i)(args), - LogLevel::Debug => (logger.d)(args), - _ => () + } + + fn write(level: LogLevel, msg: &[u8]) { + if level == LogLevel::Info { + stdout().write_all(msg).ok(); + } else { + stderr().write_all(msg).ok(); + } + } + + let logger = Logger { + fmt: print, + write, + flags: LogFlag::ExitOnError, + }; + unsafe { + LOGGER = logger; } } diff --git a/native/rust/core/src/lib.rs b/native/rust/core/src/lib.rs index 358fc7052..0d8ab66c8 100644 --- a/native/rust/core/src/lib.rs +++ b/native/rust/core/src/lib.rs @@ -7,12 +7,6 @@ mod logging; pub mod ffi { extern "Rust" { fn rust_test_entry(); - } -} - -#[cxx::bridge(namespace = "rust")] -pub mod ffi2 { - extern "Rust" { fn android_logging(); fn magisk_logging(); fn zygisk_logging(); diff --git a/native/rust/core/src/logging.rs b/native/rust/core/src/logging.rs index 83b6b6c8e..dc213cdfe 100644 --- a/native/rust/core/src/logging.rs +++ b/native/rust/core/src/logging.rs @@ -1,5 +1,6 @@ use std::fmt::Arguments; use base::*; +use base::ffi::LogLevel; #[allow(dead_code, non_camel_case_types)] #[repr(i32)] @@ -21,20 +22,34 @@ extern "C" { fn zygisk_log_write(prio: i32, msg: *const u8, len: i32); } +fn level_to_prio(level: LogLevel) -> i32 { + match level { + LogLevel::Error => ALogPriority::ANDROID_LOG_ERROR as i32, + LogLevel::Warn => ALogPriority::ANDROID_LOG_WARN as i32, + LogLevel::Info => ALogPriority::ANDROID_LOG_INFO as i32, + LogLevel::Debug => ALogPriority::ANDROID_LOG_DEBUG as i32, + _ => 0 + } +} + pub fn android_logging() { - fn android_log_impl(prio: i32, args: Arguments) { + fn android_log_fmt(level: LogLevel, args: Arguments) { let mut buf: [u8; 4096] = [0; 4096]; fmt_to_buf(&mut buf, args); unsafe { - __android_log_write(prio, b"Magisk\0".as_ptr(), buf.as_ptr()); + __android_log_write(level_to_prio(level), b"Magisk\0".as_ptr(), buf.as_ptr()); + } + } + fn android_log_write(level: LogLevel, msg: &[u8]) { + unsafe { + __android_log_write(level_to_prio(level), b"Magisk\0".as_ptr(), msg.as_ptr()); } } let logger = Logger { - d: |args| { android_log_impl(ALogPriority::ANDROID_LOG_DEBUG as i32, args) }, - i: |args| { android_log_impl(ALogPriority::ANDROID_LOG_INFO as i32, args) }, - w: |args| { android_log_impl(ALogPriority::ANDROID_LOG_WARN as i32, args) }, - e: |args| { android_log_impl(ALogPriority::ANDROID_LOG_ERROR as i32, args) } + fmt: android_log_fmt, + write: android_log_write, + flags: 0, }; exit_on_error(false); unsafe { @@ -43,20 +58,25 @@ pub fn android_logging() { } pub fn magisk_logging() { - fn magisk_log_impl(prio: i32, args: Arguments) { + fn magisk_fmt(level: LogLevel, args: Arguments) { let mut buf: [u8; 4096] = [0; 4096]; let len = fmt_to_buf(&mut buf, args); unsafe { - __android_log_write(prio, b"Magisk\0".as_ptr(), buf.as_ptr()); - magisk_log_write(prio, buf.as_ptr(), len as i32); + __android_log_write(level_to_prio(level), b"Magisk\0".as_ptr(), buf.as_ptr()); + magisk_log_write(level_to_prio(level), buf.as_ptr(), len as i32); + } + } + fn magisk_write(level: LogLevel, msg: &[u8]) { + unsafe { + __android_log_write(level_to_prio(level), b"Magisk\0".as_ptr(), msg.as_ptr()); + magisk_log_write(level_to_prio(level), msg.as_ptr(), msg.len() as i32); } } let logger = Logger { - d: |args| { magisk_log_impl(ALogPriority::ANDROID_LOG_DEBUG as i32, args) }, - i: |args| { magisk_log_impl(ALogPriority::ANDROID_LOG_INFO as i32, args) }, - w: |args| { magisk_log_impl(ALogPriority::ANDROID_LOG_WARN as i32, args) }, - e: |args| { magisk_log_impl(ALogPriority::ANDROID_LOG_ERROR as i32, args) } + fmt: magisk_fmt, + write: magisk_write, + flags: 0, }; exit_on_error(false); unsafe { @@ -65,20 +85,25 @@ pub fn magisk_logging() { } pub fn zygisk_logging() { - fn zygisk_log_impl(prio: i32, args: Arguments) { + fn zygisk_fmt(level: LogLevel, args: Arguments) { let mut buf: [u8; 4096] = [0; 4096]; let len = fmt_to_buf(&mut buf, args); unsafe { - __android_log_write(prio, b"Magisk\0".as_ptr(), buf.as_ptr()); - zygisk_log_write(prio, buf.as_ptr(), len as i32); + __android_log_write(level_to_prio(level), b"Magisk\0".as_ptr(), buf.as_ptr()); + zygisk_log_write(level_to_prio(level), buf.as_ptr(), len as i32); + } + } + fn zygisk_write(level: LogLevel, msg: &[u8]) { + unsafe { + __android_log_write(level_to_prio(level), b"Magisk\0".as_ptr(), msg.as_ptr()); + zygisk_log_write(level_to_prio(level), msg.as_ptr(), msg.len() as i32); } } let logger = Logger { - d: |args| { zygisk_log_impl(ALogPriority::ANDROID_LOG_DEBUG as i32, args) }, - i: |args| { zygisk_log_impl(ALogPriority::ANDROID_LOG_INFO as i32, args) }, - w: |args| { zygisk_log_impl(ALogPriority::ANDROID_LOG_WARN as i32, args) }, - e: |args| { zygisk_log_impl(ALogPriority::ANDROID_LOG_ERROR as i32, args) } + fmt: zygisk_fmt, + write: zygisk_write, + flags: 0, }; exit_on_error(false); unsafe { diff --git a/native/rust/init/src/logging.rs b/native/rust/init/src/logging.rs index a1285ca82..3b0d7ef1a 100644 --- a/native/rust/init/src/logging.rs +++ b/native/rust/init/src/logging.rs @@ -1,15 +1,16 @@ use std::fmt::Arguments; use base::*; +use base::ffi::LogLevel; extern "C" { fn klog_write(msg: *const u8, len: i32); } pub fn setup_klog() { - fn klog_impl(args: Arguments) { - const PREFIX: &[u8; 12] = b"magiskinit: "; - const PFX_LEN: usize = PREFIX.len(); + const PREFIX: &[u8; 12] = b"magiskinit: "; + const PFX_LEN: usize = PREFIX.len(); + fn klog_fmt(_: LogLevel, args: Arguments) { let mut buf: [u8; 4096] = [0; 4096]; buf[..PFX_LEN].copy_from_slice(PREFIX); let len = fmt_to_buf(&mut buf[PFX_LEN..], args) + PFX_LEN; @@ -18,11 +19,16 @@ pub fn setup_klog() { } } + fn klog_write_impl(_: LogLevel, msg: &[u8]) { + unsafe { + klog_write(msg.as_ptr(), msg.len() as i32); + } + } + let logger = Logger { - d: klog_impl, - i: klog_impl, - w: klog_impl, - e: klog_impl, + fmt: klog_fmt, + write: klog_write_impl, + flags: 0, }; exit_on_error(false); unsafe {