From 2e52875b5018351ace8e754676e483b37c6e3cb5 Mon Sep 17 00:00:00 2001 From: topjohnwu Date: Tue, 5 Jul 2022 21:13:09 -0700 Subject: [PATCH] Move all logging into Rust --- native/jni/base/logging.cpp | 53 +++++++++++++++----- native/jni/base/logging.hpp | 1 + native/jni/core/logging.cpp | 43 ++++------------ native/jni/include/daemon.hpp | 2 +- native/jni/init/getinfo.cpp | 10 ++-- native/jni/init/init.cpp | 2 + native/jni/init/init.hpp | 1 + native/jni/zygisk/entry.cpp | 13 ++--- native/rust/Cargo.lock | 1 + native/rust/base/src/lib.rs | 6 ++- native/rust/base/src/logging.rs | 23 +++++---- native/rust/base/src/misc.rs | 41 ++++++++++++++++ native/rust/core/src/lib.rs | 12 +++++ native/rust/core/src/logging.rs | 87 +++++++++++++++++++++++++++++++++ native/rust/init/Cargo.toml | 1 + native/rust/init/src/lib.rs | 10 ++++ native/rust/init/src/logging.rs | 31 ++++++++++++ 17 files changed, 263 insertions(+), 74 deletions(-) create mode 100644 native/rust/base/src/misc.rs create mode 100644 native/rust/core/src/logging.rs create mode 100644 native/rust/init/src/logging.rs diff --git a/native/jni/base/logging.cpp b/native/jni/base/logging.cpp index 1b5258d90..94d7c0f38 100644 --- a/native/jni/base/logging.cpp +++ b/native/jni/base/logging.cpp @@ -1,6 +1,8 @@ #include #include +#include + #include #include @@ -19,21 +21,47 @@ log_callback log_cb = { }; static bool EXIT_ON_ERROR = false; -static void fmt_and_log_with_rs(LogLevel level, const char *fmt, va_list ap) { +static int fmt_and_log_with_rs(LogLevel level, const char *fmt, va_list ap) { char buf[4096]; - int len = vsnprintf(buf, sizeof(buf), fmt, ap); - if (len > 0 && buf[len - 1] == '\n') { - // It's unfortunate that all logging on the C++ side always manually include - // a newline at the end due to how it was originally implemented. - // The logging infrastructure on the rust side does NOT expect a newline - // at the end, so we will have to strip it out before sending it over. - buf[len - 1] = '\0'; - } + int ret = vsnprintf(buf, sizeof(buf), fmt, ap); log_with_rs(level, buf); + return ret; +} + +// Used to override external C library logging +extern "C" int magisk_log_print(int prio, const char *tag, const char *fmt, ...) { + LogLevel level; + switch (prio) { + case ANDROID_LOG_DEBUG: + level = LogLevel::Debug; + break; + case ANDROID_LOG_INFO: + level = LogLevel::Info; + break; + case ANDROID_LOG_WARN: + level = LogLevel::Warn; + break; + case ANDROID_LOG_ERROR: + level = LogLevel::Error; + break; + default: + return 0; + } + + char fmt_buf[4096]; + auto len = strlcpy(fmt_buf, tag, sizeof(fmt_buf)); + // Prevent format specifications in the tag + std::replace(fmt_buf, fmt_buf + len, '%', '_'); + 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); + va_end(argv); + return ret; } #define rlog(prio) [](auto fmt, auto ap) { fmt_and_log_with_rs(LogLevel::prio, fmt, ap); } -static void forward_logging_to_rs() { +void forward_logging_to_rs() { log_cb.d = rlog(Debug); log_cb.i = rlog(Info); log_cb.w = rlog(Warn); @@ -41,12 +69,13 @@ static void forward_logging_to_rs() { } void cmdline_logging() { - rs::logging::cmdline_logging(); + rust::cmdline_logging(); forward_logging_to_rs(); + exit_on_error(true); } void exit_on_error(bool b) { - rs::logging::exit_on_error(b); + rust::exit_on_error(b); EXIT_ON_ERROR = b; } diff --git a/native/jni/base/logging.hpp b/native/jni/base/logging.hpp index 75c867803..bd281b1f7 100644 --- a/native/jni/base/logging.hpp +++ b/native/jni/base/logging.hpp @@ -20,5 +20,6 @@ void LOGE(const char *fmt, ...) __printflike(1, 2); 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/logging.cpp b/native/jni/core/logging.cpp index 1a56c5df4..72be31680 100644 --- a/native/jni/core/logging.cpp +++ b/native/jni/core/logging.cpp @@ -35,7 +35,7 @@ void setup_logfile(bool reset) { } // Maximum message length for pipes to transfer atomically -#define MAX_MSG_LEN (PIPE_BUF - sizeof(log_meta)) +#define MAX_MSG_LEN (int) (PIPE_BUF - sizeof(log_meta)) static void *logfile_writer(void *arg) { int pipefd = (long) arg; @@ -124,11 +124,11 @@ static void *logfile_writer(void *arg) { } } -int magisk_log(int prio, const char *fmt, va_list ap) { - char buf[MAX_MSG_LEN + 1]; - int len = vsnprintf(buf, sizeof(buf), fmt, ap); - +void magisk_log_write(int prio, const char *msg, int len) { if (logd_fd >= 0) { + // Truncate + len = std::min(MAX_MSG_LEN, len); + log_meta meta = { .prio = prio, .len = len, @@ -139,7 +139,7 @@ int magisk_log(int prio, const char *fmt, va_list ap) { iovec iov[2]; iov[0].iov_base = &meta; iov[0].iov_len = sizeof(meta); - iov[1].iov_base = buf; + iov[1].iov_base = (void *) msg; iov[1].iov_len = len; if (writev(logd_fd, iov, 2) < 0) { @@ -147,40 +147,17 @@ int magisk_log(int prio, const char *fmt, va_list ap) { close(logd_fd.exchange(-1)); } } - __android_log_write(prio, "Magisk", buf); - - return len; } -// Used to override external C library logging -extern "C" int magisk_log_print(int prio, const char *tag, const char *fmt, ...) { - char buf[4096]; - auto len = strlcpy(buf, tag, sizeof(buf)); - // Prevent format specifications in the tag - std::replace(buf, buf + len, '%', '_'); - snprintf(buf + len, sizeof(buf) - len, ": %s", fmt); - va_list argv; - va_start(argv, fmt); - int ret = magisk_log(prio, buf, argv); - va_end(argv); - return ret; -} - -#define mlog(prio) [](auto fmt, auto ap){ magisk_log(ANDROID_LOG_##prio, fmt, ap); } void magisk_logging() { - log_cb.d = mlog(DEBUG); - log_cb.i = mlog(INFO); - log_cb.w = mlog(WARN); - log_cb.e = mlog(ERROR); + rust::magisk_logging(); + forward_logging_to_rs(); exit_on_error(false); } -#define alog(prio) [](auto fmt, auto ap){ __android_log_vprint(ANDROID_LOG_##prio, "Magisk", fmt, ap); } void android_logging() { - log_cb.d = alog(DEBUG); - log_cb.i = alog(INFO); - log_cb.w = alog(WARN); - log_cb.e = alog(ERROR); + rust::android_logging(); + forward_logging_to_rs(); exit_on_error(false); } diff --git a/native/jni/include/daemon.hpp b/native/jni/include/daemon.hpp index 05d61a562..da5c8cbd6 100644 --- a/native/jni/include/daemon.hpp +++ b/native/jni/include/daemon.hpp @@ -81,8 +81,8 @@ void exec_task(std::function &&task); // Logging extern std::atomic logd_fd; -int magisk_log(int prio, const char *fmt, va_list ap); void android_logging(); +extern "C" void magisk_log_write(int prio, const char *msg, int len); // Daemon handlers void post_fs_data(int client); diff --git a/native/jni/init/getinfo.cpp b/native/jni/init/getinfo.cpp index 1b08c1769..7e85dd8ae 100644 --- a/native/jni/init/getinfo.cpp +++ b/native/jni/init/getinfo.cpp @@ -118,10 +118,8 @@ static bool check_key_combo() { } static FILE *kmsg; -static char kmsg_buf[4096]; -static void vprintk(const char *fmt, va_list ap) { - vsnprintf(kmsg_buf + 12, sizeof(kmsg_buf) - 12, fmt, ap); - fprintf(kmsg, "%s", kmsg_buf); +extern "C" void klog_write(const char *msg, int len) { + fprintf(kmsg, "%.*s", len, msg); } void setup_klog() { // Shut down first 3 fds @@ -149,9 +147,9 @@ void setup_klog() { kmsg = fdopen(fd, "w"); setbuf(kmsg, nullptr); - log_cb.d = log_cb.i = log_cb.w = log_cb.e = vprintk; + rust::setup_klog(); + forward_logging_to_rs(); exit_on_error(false); - strcpy(kmsg_buf, "magiskinit: "); // Disable kmsg rate limiting if (FILE *rate = fopen("/proc/sys/kernel/printk_devkmsg", "w")) { diff --git a/native/jni/init/init.cpp b/native/jni/init/init.cpp index bf3a517f3..c81d3dbd6 100644 --- a/native/jni/init/init.cpp +++ b/native/jni/init/init.cpp @@ -22,6 +22,8 @@ #include "init.hpp" +#include + using namespace std; bool unxz(int fd, const uint8_t *buf, size_t size) { diff --git a/native/jni/init/init.hpp b/native/jni/init/init.hpp index 1908202d2..519ca4272 100644 --- a/native/jni/init/init.hpp +++ b/native/jni/init/init.hpp @@ -1,4 +1,5 @@ #include +#include using kv_pairs = std::vector>; diff --git a/native/jni/zygisk/entry.cpp b/native/jni/zygisk/entry.cpp index 2fec0b40a..8977c6b91 100644 --- a/native/jni/zygisk/entry.cpp +++ b/native/jni/zygisk/entry.cpp @@ -17,14 +17,9 @@ using namespace std; void *self_handle = nullptr; -static void zygisk_log(int prio, const char *fmt, va_list ap); - -#define zlog(prio) [](auto fmt, auto ap){ zygisk_log(ANDROID_LOG_##prio, fmt, ap); } static void zygisk_logging() { - log_cb.d = zlog(DEBUG); - log_cb.i = zlog(INFO); - log_cb.w = zlog(WARN); - log_cb.e = zlog(ERROR); + rust::zygisk_logging(); + forward_logging_to_rs(); exit_on_error(false); } @@ -114,7 +109,7 @@ static void zygisk_init() { // The following code runs in zygote/app process -static void zygisk_log(int prio, const char *fmt, va_list ap) { +extern "C" void zygisk_log_write(int prio, const char *msg, int len) { // If we don't have log pipe set, ask magiskd for it // This could happen multiple times in zygote because it was closed to prevent crashing if (logd_fd < 0) { @@ -139,7 +134,7 @@ static void zygisk_log(int prio, const char *fmt, va_list ap) { sigaddset(&mask, SIGPIPE); pthread_sigmask(SIG_BLOCK, &mask, &orig_mask); } - magisk_log(prio, fmt, ap); + magisk_log_write(prio, msg, len); if (sig) { timespec ts{}; sigtimedwait(&mask, nullptr, &ts); diff --git a/native/rust/Cargo.lock b/native/rust/Cargo.lock index 1a64b59c5..6ed008895 100644 --- a/native/rust/Cargo.lock +++ b/native/rust/Cargo.lock @@ -57,6 +57,7 @@ name = "magiskinit" version = "0.1.0" dependencies = [ "base", + "cxx", ] [[package]] diff --git a/native/rust/base/src/lib.rs b/native/rust/base/src/lib.rs index 3a3bc778b..98d4d5450 100644 --- a/native/rust/base/src/lib.rs +++ b/native/rust/base/src/lib.rs @@ -1,6 +1,10 @@ +#![feature(format_args_nl)] + pub use logging::*; +pub use misc::*; mod logging; +mod misc; #[cxx::bridge] pub mod ffi { @@ -16,7 +20,7 @@ pub mod ffi { } } -#[cxx::bridge(namespace = "rs::logging")] +#[cxx::bridge(namespace = "rust")] pub mod ffi2 { extern "Rust" { fn cmdline_logging(); diff --git a/native/rust/base/src/logging.rs b/native/rust/base/src/logging.rs index e0587a506..e031e542a 100644 --- a/native/rust/base/src/logging.rs +++ b/native/rust/base/src/logging.rs @@ -23,10 +23,6 @@ pub struct Logger { pub fn nop_log(_: Arguments) {} -fn println(args: Arguments) { println!("{}", args); } - -fn eprintln(args: Arguments) { eprintln!("{}", args); } - pub fn log_with_rs(level: LogLevel, msg: &str) { log_impl(level, format_args!("{}", msg)); } @@ -36,11 +32,14 @@ pub fn exit_on_error(b: bool) { } pub fn cmdline_logging() { + fn print(args: Arguments) { print!("{}", args); } + fn eprint(args: Arguments) { eprint!("{}", args); } + let logger = Logger { - d: eprintln, - i: println, - w: eprintln, - e: eprintln, + d: eprint, + i: print, + w: eprint, + e: eprint, }; unsafe { LOGGER = logger; @@ -65,23 +64,23 @@ pub fn log_impl(level: LogLevel, args: Arguments) { #[macro_export] macro_rules! error { - ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Error, format_args!($($arg)+))) + ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Error, format_args_nl!($($arg)+))) } #[macro_export] macro_rules! warn { - ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Warn, format_args!($($arg)+))) + ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Warn, format_args_nl!($($arg)+))) } #[macro_export] macro_rules! info { - ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Info, format_args!($($arg)+))) + ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Info, format_args_nl!($($arg)+))) } #[cfg(debug_assertions)] #[macro_export] macro_rules! debug { - ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Debug, format_args!($($arg)+))) + ($($arg:tt)+) => ($crate::log_impl($crate::ffi::LogLevel::Debug, format_args_nl!($($arg)+))) } #[cfg(not(debug_assertions))] diff --git a/native/rust/base/src/misc.rs b/native/rust/base/src/misc.rs new file mode 100644 index 000000000..9f2fb2b0d --- /dev/null +++ b/native/rust/base/src/misc.rs @@ -0,0 +1,41 @@ +use std::cmp::min; +use std::fmt; +use std::fmt::Arguments; + +struct BufFmtWriter<'a> { + buf: &'a mut [u8], + used: usize, +} + +impl<'a> BufFmtWriter<'a> { + fn new(buf: &'a mut [u8]) -> Self { + BufFmtWriter { buf, used: 0 } + } +} + +impl<'a> fmt::Write for BufFmtWriter<'a> { + // The buffer should always be null terminated + fn write_str(&mut self, s: &str) -> fmt::Result { + if self.used >= self.buf.len() - 1 { + // Silent truncate + return Ok(()); + } + let remain = &mut self.buf[self.used..]; + let s_bytes = s.as_bytes(); + let copied = min(s_bytes.len(), remain.len() - 1); + remain[..copied].copy_from_slice(&s_bytes[..copied]); + self.used += copied; + self.buf[self.used] = b'\0'; + // Silent truncate + Ok(()) + } +} + +pub fn fmt_to_buf(buf: &mut [u8], args: Arguments) -> usize { + let mut w = BufFmtWriter::new(buf); + if let Ok(()) = fmt::write(&mut w, args) { + w.used + } else { + 0 + } +} diff --git a/native/rust/core/src/lib.rs b/native/rust/core/src/lib.rs index ec659ef92..358fc7052 100644 --- a/native/rust/core/src/lib.rs +++ b/native/rust/core/src/lib.rs @@ -1,4 +1,7 @@ pub use base; +pub use logging::*; + +mod logging; #[cxx::bridge] pub mod ffi { @@ -7,4 +10,13 @@ pub mod ffi { } } +#[cxx::bridge(namespace = "rust")] +pub mod ffi2 { + extern "Rust" { + fn android_logging(); + fn magisk_logging(); + fn zygisk_logging(); + } +} + fn rust_test_entry() {} diff --git a/native/rust/core/src/logging.rs b/native/rust/core/src/logging.rs new file mode 100644 index 000000000..83b6b6c8e --- /dev/null +++ b/native/rust/core/src/logging.rs @@ -0,0 +1,87 @@ +use std::fmt::Arguments; +use base::*; + +#[allow(dead_code, non_camel_case_types)] +#[repr(i32)] +enum ALogPriority { + ANDROID_LOG_UNKNOWN = 0, + ANDROID_LOG_DEFAULT, + ANDROID_LOG_VERBOSE, + ANDROID_LOG_DEBUG, + ANDROID_LOG_INFO, + ANDROID_LOG_WARN, + ANDROID_LOG_ERROR, + ANDROID_LOG_FATAL, + ANDROID_LOG_SILENT, +} + +extern "C" { + fn __android_log_write(prio: i32, tag: *const u8, msg: *const u8); + fn magisk_log_write(prio: i32, msg: *const u8, len: i32); + fn zygisk_log_write(prio: i32, msg: *const u8, len: i32); +} + +pub fn android_logging() { + fn android_log_impl(prio: i32, 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()); + } + } + + 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) } + }; + exit_on_error(false); + unsafe { + LOGGER = logger; + } +} + +pub fn magisk_logging() { + fn magisk_log_impl(prio: i32, 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); + } + } + + 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) } + }; + exit_on_error(false); + unsafe { + LOGGER = logger; + } +} + +pub fn zygisk_logging() { + fn zygisk_log_impl(prio: i32, 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); + } + } + + 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) } + }; + exit_on_error(false); + unsafe { + LOGGER = logger; + } +} diff --git a/native/rust/init/Cargo.toml b/native/rust/init/Cargo.toml index b0e6084dc..d4335596c 100644 --- a/native/rust/init/Cargo.toml +++ b/native/rust/init/Cargo.toml @@ -8,3 +8,4 @@ crate-type = ["staticlib"] [dependencies] base = { path = "../base" } +cxx = "1.0.69" diff --git a/native/rust/init/src/lib.rs b/native/rust/init/src/lib.rs index 8411b1d59..17e45b5e9 100644 --- a/native/rust/init/src/lib.rs +++ b/native/rust/init/src/lib.rs @@ -1 +1,11 @@ pub use base; +pub use logging::*; + +mod logging; + +#[cxx::bridge(namespace = "rust")] +pub mod ffi2 { + extern "Rust" { + fn setup_klog(); + } +} diff --git a/native/rust/init/src/logging.rs b/native/rust/init/src/logging.rs new file mode 100644 index 000000000..a1285ca82 --- /dev/null +++ b/native/rust/init/src/logging.rs @@ -0,0 +1,31 @@ +use std::fmt::Arguments; +use base::*; + +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(); + + 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; + unsafe { + klog_write(buf.as_ptr(), len as i32); + } + } + + let logger = Logger { + d: klog_impl, + i: klog_impl, + w: klog_impl, + e: klog_impl, + }; + exit_on_error(false); + unsafe { + LOGGER = logger; + } +}