Move all logging into Rust

native/jni/base/logging.cpp

@@ -1,6 +1,8 @@
 #include <cstdio>
 #include <cstdlib>
 
+#include <android/log.h>
+
 #include <flags.h>
 #include <base.hpp>
 
@@ -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);
+    int ret = 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';
-    }
     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;
 }
 

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);

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) {
+void magisk_log_write(int prio, const char *msg, int len) {
-    char buf[MAX_MSG_LEN + 1];
-    int len = vsnprintf(buf, sizeof(buf), fmt, ap);
-
     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);
+    rust::magisk_logging();
-    log_cb.i = mlog(INFO);
+    forward_logging_to_rs();
-    log_cb.w = mlog(WARN);
-    log_cb.e = mlog(ERROR);
     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);
+    rust::android_logging();
-    log_cb.i = alog(INFO);
+    forward_logging_to_rs();
-    log_cb.w = alog(WARN);
-    log_cb.e = alog(ERROR);
     exit_on_error(false);
 }
 

native/jni/include/daemon.hpp

@@ -81,8 +81,8 @@ void exec_task(std::function<void()> &&task);
 
 // Logging
 extern std::atomic<int> 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);

native/jni/init/getinfo.cpp

@@ -118,10 +118,8 @@ static bool check_key_combo() {
 }
 
 static FILE *kmsg;
-static char kmsg_buf[4096];
+extern "C" void klog_write(const char *msg, int len) {
-static void vprintk(const char *fmt, va_list ap) {
+    fprintf(kmsg, "%.*s", len, msg);
-    vsnprintf(kmsg_buf + 12, sizeof(kmsg_buf) - 12, fmt, ap);
-    fprintf(kmsg, "%s", kmsg_buf);
 }
 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")) {

native/jni/init/init.cpp

@@ -22,6 +22,8 @@
 
 #include "init.hpp"
 
+#include <init-rs.cpp>
+
 using namespace std;
 
 bool unxz(int fd, const uint8_t *buf, size_t size) {

native/jni/init/init.hpp

@@ -1,4 +1,5 @@
 #include <base.hpp>
+#include <init-rs.hpp>
 
 using kv_pairs = std::vector<std::pair<std::string, std::string>>;
 

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);
+    rust::zygisk_logging();
-    log_cb.i = zlog(INFO);
+    forward_logging_to_rs();
-    log_cb.w = zlog(WARN);
-    log_cb.e = zlog(ERROR);
     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);

native/rust/Cargo.lock

@@ -57,6 +57,7 @@ name = "magiskinit"
 version = "0.1.0"
 dependencies = [
  "base",
+ "cxx",
 ]
 
 [[package]]

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();

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,
+        d: eprint,
-        i: println,
+        i: print,
-        w: eprintln,
+        w: eprint,
-        e: eprintln,
+        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))]

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
+    }
+}

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() {}

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;
+    }
+}

native/rust/init/Cargo.toml

@@ -8,3 +8,4 @@ crate-type = ["staticlib"]
 
 [dependencies]
 base = { path = "../base" }
+cxx = "1.0.69"

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();
+    }
+}

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;
+    }
+}