Implement logging purely in Rust

native/src/core/logging.rs

@@ -1,8 +1,27 @@
-use base::ffi::LogLevel;
-use base::*;
+use std::cmp::min;
+use std::ffi::{c_char, c_void};
 use std::fmt::Arguments;
+use std::fs::File;
+use std::io::{IoSlice, Read, Write};
+use std::os::fd::{AsRawFd, FromRawFd, RawFd};
+use std::ptr::null_mut;
+use std::{fs, io};
+
+use num_derive::{FromPrimitive, ToPrimitive};
+use num_traits::FromPrimitive;
+
+use base::ffi::LogLevel;
+use base::libc::{
+    getpid, gettid, gettimeofday, localtime_r, pipe2, pthread_sigmask, sigaddset, sigset_t,
+    sigtimedwait, timespec, timeval, tm, O_CLOEXEC, PIPE_BUF, SIGPIPE, SIG_BLOCK, SIG_SETMASK,
+};
+use base::*;
+
+use crate::daemon::{MagiskD, MAGISKD};
+use crate::logging::LogFile::{Actual, Buffer};
 
 #[allow(dead_code, non_camel_case_types)]
+#[derive(FromPrimitive, ToPrimitive)]
 #[repr(i32)]
 enum ALogPriority {
     ANDROID_LOG_UNKNOWN = 0,
@@ -16,10 +35,14 @@ enum ALogPriority {
     ANDROID_LOG_SILENT,
 }
 
+type ThreadEntry = extern "C" fn(*mut c_void) -> *mut c_void;
+
 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);
+    fn __android_log_write(prio: i32, tag: *const c_char, msg: *const u8);
+    fn strftime(buf: *mut c_char, len: usize, fmt: *const c_char, tm: *const tm) -> usize;
+
+    fn zygisk_fetch_logd() -> RawFd;
+    fn new_daemon_thread(entry: ThreadEntry, arg: *mut c_void);
 }
 
 fn level_to_prio(level: LogLevel) -> i32 {
@@ -37,12 +60,12 @@ pub fn android_logging() {
         let mut buf: [u8; 4096] = [0; 4096];
         fmt_to_buf(&mut buf, args);
         unsafe {
-            __android_log_write(level_to_prio(level), b"Magisk\0".as_ptr(), buf.as_ptr());
+            __android_log_write(level_to_prio(level), str_ptr!("Magisk"), 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());
+            __android_log_write(level_to_prio(level), str_ptr!("Magisk"), msg.as_ptr());
         }
     }
 
@@ -62,15 +85,15 @@ pub fn magisk_logging() {
         let mut buf: [u8; 4096] = [0; 4096];
         let len = fmt_to_buf(&mut buf, args);
         unsafe {
-            __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);
+            __android_log_write(level_to_prio(level), str_ptr!("Magisk"), buf.as_ptr());
         }
+        magisk_log_write(level_to_prio(level), &buf[..len]);
     }
     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);
+            __android_log_write(level_to_prio(level), str_ptr!("Magisk"), msg.as_ptr());
         }
+        magisk_log_write(level_to_prio(level), &msg);
     }
 
     let logger = Logger {
@@ -89,15 +112,15 @@ pub fn zygisk_logging() {
         let mut buf: [u8; 4096] = [0; 4096];
         let len = fmt_to_buf(&mut buf, args);
         unsafe {
-            __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);
+            __android_log_write(level_to_prio(level), str_ptr!("Magisk"), buf.as_ptr());
         }
+        zygisk_log_write(level_to_prio(level), &buf[..len]);
     }
     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);
+            __android_log_write(level_to_prio(level), str_ptr!("Magisk"), msg.as_ptr());
         }
+        zygisk_log_write(level_to_prio(level), &msg);
     }
 
     let logger = Logger {
@@ -110,3 +133,250 @@ pub fn zygisk_logging() {
         LOGGER = logger;
     }
 }
+
+#[derive(Default)]
+#[repr(C)]
+struct LogMeta {
+    prio: i32,
+    len: i32,
+    pid: i32,
+    tid: i32,
+}
+
+const MAX_MSG_LEN: usize = PIPE_BUF - std::mem::size_of::<LogMeta>();
+
+fn do_magisk_log_write(logd: &mut File, prio: i32, msg: &[u8]) -> io::Result<usize> {
+    // Truncate message if needed
+    let len = min(MAX_MSG_LEN, msg.len());
+    let msg = &msg[..len];
+
+    let meta = LogMeta {
+        prio,
+        len: len as i32,
+        pid: unsafe { getpid() },
+        tid: unsafe { gettid() },
+    };
+
+    let io1 = IoSlice::new(meta.as_raw_bytes());
+    let io2 = IoSlice::new(msg);
+    logd.write_vectored(&[io1, io2])
+}
+
+fn magisk_log_write(prio: i32, msg: &[u8]) {
+    let magiskd = match MAGISKD.get() {
+        None => return,
+        Some(s) => s,
+    };
+
+    let logd_cell = magiskd.logd.lock().unwrap();
+    let mut logd_ref = logd_cell.borrow_mut();
+    let logd = match logd_ref.as_mut() {
+        None => return,
+        Some(s) => s,
+    };
+
+    let result = do_magisk_log_write(logd, prio, &msg);
+
+    // If any error occurs, shut down the logd pipe
+    if result.is_err() {
+        *logd_ref = None;
+    }
+}
+
+fn zygisk_log_write(prio: i32, msg: &[u8]) {
+    let magiskd = match MAGISKD.get() {
+        None => return,
+        Some(s) => s,
+    };
+
+    let logd_cell = magiskd.logd.lock().unwrap();
+    let mut logd_ref = logd_cell.borrow_mut();
+    if logd_ref.is_none() {
+        android_logging();
+        unsafe {
+            let fd = zygisk_fetch_logd();
+            if fd < 0 {
+                return;
+            }
+            *logd_ref = Some(File::from_raw_fd(fd));
+        }
+        // Only re-enable zygisk logging if success
+        zygisk_logging();
+    };
+    let logd = logd_ref.as_mut().unwrap();
+
+    // Block SIGPIPE
+    let mut mask: sigset_t;
+    let mut orig_mask: sigset_t;
+    unsafe {
+        mask = std::mem::zeroed();
+        orig_mask = std::mem::zeroed();
+        sigaddset(&mut mask, SIGPIPE);
+        pthread_sigmask(SIG_BLOCK, &mask, &mut orig_mask);
+    }
+
+    let result = do_magisk_log_write(logd, prio, &msg);
+
+    // Consume SIGPIPE if exists, then restore mask
+    unsafe {
+        let mut ts: timespec = std::mem::zeroed();
+        sigtimedwait(&mask, null_mut(), &ts);
+        pthread_sigmask(SIG_SETMASK, &orig_mask, null_mut());
+    }
+
+    // If any error occurs, shut down the logd pipe
+    if result.is_err() {
+        *logd_ref = None;
+    }
+}
+
+// The following is implementation for the logging daemon
+
+enum LogFile<'a> {
+    Buffer(&'a mut Vec<u8>),
+    Actual(File),
+}
+
+impl LogFile<'_> {
+    fn as_write(&mut self) -> &mut dyn Write {
+        match self {
+            Buffer(e) => e,
+            Actual(ref mut e) => e,
+        }
+    }
+}
+
+impl FlatData for LogMeta {}
+
+extern "C" fn logfile_writer(arg: *mut c_void) -> *mut c_void {
+    fn writer_loop(pipefd: RawFd) -> io::Result<()> {
+        let mut pipe = unsafe { File::from_raw_fd(pipefd) };
+        let mut tmp = Vec::new();
+        let mut logfile: LogFile = Buffer(&mut tmp);
+
+        let mut meta = LogMeta::default();
+        let mut buf: [u8; MAX_MSG_LEN] = [0; MAX_MSG_LEN];
+        let mut aux: [u8; 64] = [0; 64];
+
+        loop {
+            // Read request
+            pipe.read_exact(meta.as_raw_bytes_mut())?;
+
+            if meta.prio < 0 {
+                if matches!(logfile, LogFile::Buffer(_)) {
+                    fs::rename(LOGFILE!(), concat!(LOGFILE!(), ".bak")).ok();
+                    let mut out = File::create(LOGFILE!())?;
+                    out.write_all(tmp.as_slice())?;
+                    tmp = Vec::new();
+                    logfile = Actual(out);
+                }
+                continue;
+            }
+
+            if meta.len < 0 || meta.len > buf.len() as i32 {
+                continue;
+            }
+
+            // Read the rest of the message
+            let msg = &mut buf[..(meta.len as usize)];
+            pipe.read_exact(msg)?;
+
+            // Start building the log string
+
+            let prio =
+                ALogPriority::from_i32(meta.prio).unwrap_or(ALogPriority::ANDROID_LOG_UNKNOWN);
+            let prio = match prio {
+                ALogPriority::ANDROID_LOG_VERBOSE => 'V',
+                ALogPriority::ANDROID_LOG_DEBUG => 'D',
+                ALogPriority::ANDROID_LOG_INFO => 'I',
+                ALogPriority::ANDROID_LOG_WARN => 'W',
+                ALogPriority::ANDROID_LOG_ERROR => 'E',
+                // Unsupported values, skip
+                _ => continue,
+            };
+
+            // Note: the obvious better implementation is to use the rust chrono crate, however
+            // the crate cannot fetch the proper local timezone without pulling in a bunch of
+            // timezone handling code. To reduce final binary size, fallback to use libc.
+            let mut aux_len: usize;
+            unsafe {
+                let mut tv: timeval = std::mem::zeroed();
+                let mut tm: tm = std::mem::zeroed();
+                gettimeofday(&mut tv, null_mut());
+                localtime_r(&tv.tv_sec, &mut tm);
+                aux_len = strftime(
+                    aux.as_mut_ptr().cast(),
+                    aux.len(),
+                    str_ptr!("%m-%d %T"),
+                    &tm,
+                ) as usize;
+                let ms = tv.tv_usec / 1000;
+                aux_len += bfmt!(
+                    &mut aux[aux_len..],
+                    ".{:03} {:5} {:5} {} : ",
+                    ms,
+                    meta.pid,
+                    meta.tid,
+                    prio
+                );
+            }
+
+            let io1 = IoSlice::new(&aux[..aux_len]);
+            let io2 = IoSlice::new(msg);
+            logfile.as_write().write_vectored(&[io1, io2])?;
+        }
+    }
+
+    writer_loop(arg as RawFd).ok();
+    // If any error occurs, shut down the logd pipe
+    if let Some(magiskd) = MAGISKD.get() {
+        magiskd.close_log_pipe();
+    }
+    null_mut()
+}
+
+impl MagiskD {
+    pub fn start_log_daemon(&self) {
+        let mut fds: [i32; 2] = [0; 2];
+        unsafe {
+            if pipe2(fds.as_mut_ptr(), O_CLOEXEC) == 0 {
+                let logd = self.logd.lock().unwrap();
+                *logd.borrow_mut() = Some(File::from_raw_fd(fds[1]));
+                new_daemon_thread(logfile_writer, fds[0] as *mut c_void);
+            }
+        }
+    }
+
+    pub fn get_log_pipe(&self) -> RawFd {
+        let logd_cell = self.logd.lock().unwrap();
+        let logd_ref = logd_cell.borrow();
+        let logd = logd_ref.as_ref();
+        match logd {
+            None => -1,
+            Some(s) => s.as_raw_fd(),
+        }
+    }
+
+    pub fn close_log_pipe(&self) {
+        let guard = self.logd.lock().unwrap();
+        *guard.borrow_mut() = None;
+    }
+
+    pub fn setup_logfile(&self) {
+        let logd_cell = self.logd.lock().unwrap();
+        let mut logd_ref = logd_cell.borrow_mut();
+        let logd = match logd_ref.as_mut() {
+            None => return,
+            Some(s) => s,
+        };
+
+        let meta = LogMeta {
+            prio: -1,
+            len: 0,
+            pid: 0,
+            tid: 0,
+        };
+
+        logd.write_all(meta.as_raw_bytes()).ok();
+    }
+}