Revise logging code

native/jni/Android.mk

@@ -24,6 +24,7 @@ LOCAL_SRC_FILES := \
     core/scripting.cpp \
     core/restorecon.cpp \
     core/module.cpp \
+    core/logging.cpp \
     magiskhide/magiskhide.cpp \
     magiskhide/hide_utils.cpp \
     magiskhide/hide_policy.cpp \

native/jni/core/core.hpp

@@ -8,6 +8,8 @@ extern int DAEMON_STATE;
 
 void unlock_blocks();
 void reboot();
+void magisk_logging();
+void start_log_daemon();
 void setup_logfile(bool reset);
 
 // Module stuffs
@@ -23,4 +25,3 @@ void exec_common_scripts(const char *stage);
 void exec_module_scripts(const char *stage, const std::vector<std::string> &module_list);
 void install_apk(const char *apk);
 [[noreturn]] void install_module(const char *file);
-

native/jni/core/daemon.cpp

@@ -1,11 +1,7 @@
-#include <fcntl.h>
-#include <pthread.h>
 #include <csignal>
 #include <libgen.h>
 #include <sys/un.h>
-#include <sys/types.h>
 #include <sys/mount.h>
-#include <android/log.h>
 
 #include <magisk.hpp>
 #include <utils.hpp>
@@ -14,7 +10,6 @@
 #include <db.hpp>
 #include <resetprop.hpp>
 #include <flags.hpp>
-#include <stream.hpp>
 
 #include "core.hpp"
 
@@ -103,7 +98,7 @@ static void handle_request(int client) {
     ucred cred;
     get_client_cred(client, &cred);
 
-    bool is_root = cred.uid == 0;
+    bool is_root = cred.uid == UID_ROOT;
     bool is_client = verify_client(cred.pid);
     bool is_zygote = !is_client && check_zygote(cred.pid);
 
@@ -168,9 +163,6 @@ static int switch_cgroup(const char *cgroup, int pid) {
     return 0;
 }
 
-static void magisk_logging();
-static void start_log_daemon();
-
 [[noreturn]] static void daemon_entry() {
     magisk_logging();
 
@@ -247,10 +239,10 @@ static void start_log_daemon();
         return true;
     });
 
-    struct sockaddr_un sun;
+    sockaddr_un sun;
     socklen_t len = setup_sockaddr(&sun, MAIN_SOCKET);
     fd = xsocket(AF_LOCAL, SOCK_STREAM | SOCK_CLOEXEC, 0);
-    if (xbind(fd, (struct sockaddr*) &sun, len))
+    if (xbind(fd, (sockaddr*) &sun, len))
         exit(1);
     xlisten(fd, 10);
 
@@ -265,8 +257,8 @@ int connect_daemon(bool create) {
     sockaddr_un sun;
     socklen_t len = setup_sockaddr(&sun, MAIN_SOCKET);
     int fd = xsocket(AF_UNIX, SOCK_STREAM | SOCK_CLOEXEC, 0);
-    if (connect(fd, (struct sockaddr*) &sun, len)) {
+    if (connect(fd, (sockaddr*) &sun, len)) {
-        if (!create || getuid() != UID_ROOT || getgid() != UID_ROOT) {
+        if (!create || getuid() != UID_ROOT) {
             LOGE("No daemon is currently running!\n");
             exit(1);
         }
@@ -281,162 +273,3 @@ int connect_daemon(bool create) {
     }
     return fd;
 }
-
-struct log_meta {
-    int prio;
-    int len;
-    int pid;
-    int tid;
-};
-
-static atomic<int> log_sockfd = -1;
-
-void setup_logfile(bool reset) {
-    if (log_sockfd < 0)
-        return;
-
-    msghdr msg{};
-    iovec iov{};
-    msg.msg_iov = &iov;
-    msg.msg_iovlen = 1;
-
-    log_meta meta = {
-        .prio = -1,
-        .len = reset
-    };
-
-    iov.iov_base = &meta;
-    iov.iov_len = sizeof(meta);
-    sendmsg(log_sockfd, &msg, MSG_NOSIGNAL);
-}
-
-static void logfile_writer(int sockfd) {
-    run_finally close_socket([=] {
-        // Close up all logging sockets when thread dies
-        close(sockfd);
-        close(log_sockfd.exchange(-1));
-    });
-
-    char *log_buf;
-    size_t buf_len;
-    stream *log_strm = new byte_stream(log_buf, buf_len);
-
-    msghdr msg{};
-    iovec iov{};
-    msg.msg_iov = &iov;
-    msg.msg_iovlen = 1;
-
-    log_meta meta{};
-    char buf[4096];
-
-    for (;;) {
-        // Read meta data
-        iov.iov_base = &meta;
-        iov.iov_len = sizeof(meta);
-        if (recvmsg(sockfd, &msg, 0) <= 0)
-            return;
-
-        if (meta.prio < 0 && buf_len >= 0) {
-            run_finally free_buf([&] {
-                free(log_buf);
-                log_buf = nullptr;
-                buf_len = -1;
-            });
-
-            if (meta.len)
-                rename(LOGFILE, LOGFILE ".bak");
-
-            int fd = open(LOGFILE, O_WRONLY | O_APPEND | O_CREAT | O_CLOEXEC, 0644);
-            if (fd < 0)
-                return;
-            if (log_buf)
-                write(fd, log_buf, buf_len);
-
-            delete log_strm;
-            log_strm = new fd_stream(fd);
-            continue;
-        }
-
-        timeval tv;
-        tm tm;
-        gettimeofday(&tv, nullptr);
-        localtime_r(&tv.tv_sec, &tm);
-
-        // Format detailed info
-        char type;
-        switch (meta.prio) {
-            case ANDROID_LOG_DEBUG:
-                type = 'D';
-                break;
-            case ANDROID_LOG_INFO:
-                type = 'I';
-                break;
-            case ANDROID_LOG_WARN:
-                type = 'W';
-                break;
-            default:
-                type = 'E';
-                break;
-        }
-        size_t off = strftime(buf, sizeof(buf), "%m-%d %T", &tm);
-        int ms = tv.tv_usec / 1000;
-        off += snprintf(buf + off, sizeof(buf) - off,
-                ".%03d %5d %5d %c : ", ms, meta.pid, meta.tid, type);
-
-        // Read log msg
-        iov.iov_base = buf + off;
-        iov.iov_len = meta.len;
-        if (recvmsg(sockfd, &msg, 0) <= 0)
-            return;
-        log_strm->write(buf, off + meta.len);
-    }
-}
-
-static int magisk_log(int prio, const char *fmt, va_list ap) {
-    char buf[4000];
-    int len = vsnprintf(buf, sizeof(buf), fmt, ap) + 1;
-
-    if (log_sockfd >= 0) {
-        log_meta meta = {
-            .prio = prio,
-            .len = len,
-            .pid = getpid(),
-            .tid = gettid()
-        };
-
-        msghdr msg{};
-        iovec iov[2];
-        msg.msg_iov = iov;
-        msg.msg_iovlen = 2;
-
-        iov[0].iov_base = &meta;
-        iov[0].iov_len = sizeof(meta);
-        iov[1].iov_base = buf;
-        iov[1].iov_len = len;
-
-        if (sendmsg(log_sockfd, &msg, MSG_NOSIGNAL) < 0) {
-            // Stop trying to write to file
-            close(log_sockfd.exchange(-1));
-        }
-    }
-    __android_log_write(prio, "Magisk", buf);
-
-    return len - 1;
-}
-
-static void start_log_daemon() {
-    int fds[2];
-    if (socketpair(AF_UNIX, SOCK_STREAM | SOCK_CLOEXEC, 0, fds) == 0) {
-        log_sockfd = fds[0];
-        new_daemon_thread([=] { logfile_writer(fds[1]); });
-    }
-}
-
-#define mlog(prio) [](auto fmt, auto ap){ return magisk_log(ANDROID_LOG_##prio, fmt, ap); }
-static void magisk_logging() {
-    log_cb.d = mlog(DEBUG);
-    log_cb.i = mlog(INFO);
-    log_cb.w = mlog(WARN);
-    log_cb.e = mlog(ERROR);
-    log_cb.ex = nop_ex;
-}

native/jni/core/logging.cpp

@@ -0,0 +1,160 @@
+#include <sys/uio.h>
+#include <android/log.h>
+
+#include <magisk.hpp>
+#include <utils.hpp>
+#include <daemon.hpp>
+#include <stream.hpp>
+
+#include "core.hpp"
+
+using namespace std;
+
+struct log_meta {
+    int prio;
+    int len;
+    int pid;
+    int tid;
+};
+
+static atomic<int> logd_fd = -1;
+
+void setup_logfile(bool reset) {
+    if (logd_fd < 0)
+        return;
+
+    iovec iov{};
+    log_meta meta = {
+        .prio = -1,
+        .len = reset
+    };
+
+    iov.iov_base = &meta;
+    iov.iov_len = sizeof(meta);
+    writev(logd_fd, &iov, 1);
+}
+
+// Maximum message length for pipes to transfer atomically
+#define MAX_MSG_LEN  (PIPE_BUF - sizeof(log_meta))
+#define TIME_FMT_LEN 35
+
+static void logfile_writer(int pipefd) {
+    run_finally close_socket([=] {
+        // Close up all logging pipes when thread dies
+        close(pipefd);
+        close(logd_fd.exchange(-1));
+    });
+
+    struct {
+        void *data;
+        size_t len;
+    } tmp_buf{};
+    stream *strm = new byte_stream(tmp_buf.data, tmp_buf.len);
+
+    log_meta meta{};
+    char buf[MAX_MSG_LEN + TIME_FMT_LEN];
+
+    for (;;) {
+        // Read meta data
+        if (xread(pipefd, &meta, sizeof(meta)) != sizeof(meta))
+            return;
+
+        if (meta.prio < 0 && tmp_buf.len >= 0) {
+            run_finally free_buf([&] {
+                free(tmp_buf.data);
+                tmp_buf.data = nullptr;
+                tmp_buf.len = -1;
+            });
+
+            if (meta.len)
+                rename(LOGFILE, LOGFILE ".bak");
+
+            int fd = open(LOGFILE, O_WRONLY | O_APPEND | O_CREAT | O_CLOEXEC, 0644);
+            if (fd < 0)
+                return;
+            if (tmp_buf.data)
+                write(fd, tmp_buf.data, tmp_buf.len);
+
+            delete strm;
+            strm = new fd_stream(fd);
+            continue;
+        }
+
+        // Read message
+        if (xread(pipefd, buf + TIME_FMT_LEN + 1, meta.len) != meta.len)
+            return;
+
+        timeval tv;
+        tm tm;
+        gettimeofday(&tv, nullptr);
+        localtime_r(&tv.tv_sec, &tm);
+
+        // Format detailed info
+        char type;
+        switch (meta.prio) {
+            case ANDROID_LOG_DEBUG:
+                type = 'D';
+                break;
+            case ANDROID_LOG_INFO:
+                type = 'I';
+                break;
+            case ANDROID_LOG_WARN:
+                type = 'W';
+                break;
+            default:
+                type = 'E';
+                break;
+        }
+        size_t off = strftime(buf, sizeof(buf), "%m-%d %T", &tm);
+        int ms = tv.tv_usec / 1000;
+        snprintf(buf + off, sizeof(buf) - off,
+                ".%03d %5d %5d %c : ", ms, meta.pid, meta.tid, type);
+
+        strm->write(buf, TIME_FMT_LEN + meta.len);
+    }
+}
+
+static 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);
+
+    if (logd_fd >= 0) {
+        log_meta meta = {
+            .prio = prio,
+            .len = len,
+            .pid = getpid(),
+            .tid = gettid()
+        };
+
+        iovec iov[2];
+        iov[0].iov_base = &meta;
+        iov[0].iov_len = sizeof(meta);
+        iov[1].iov_base = buf;
+        iov[1].iov_len = len;
+
+        if (writev(logd_fd, iov, 2) < 0) {
+            // Stop trying to write to file
+            close(logd_fd.exchange(-1));
+        }
+    }
+    __android_log_write(prio, "Magisk", buf);
+
+    return len;
+}
+
+#define mlog(prio) [](auto fmt, auto ap){ return 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);
+    log_cb.ex = nop_ex;
+}
+
+void start_log_daemon() {
+    int fds[2];
+    if (pipe2(fds, O_CLOEXEC) == 0) {
+        logd_fd = fds[1];
+        new_daemon_thread([fd = fds[0]] { logfile_writer(fd); });
+    }
+}

native/jni/utils/logging.cpp

@@ -1,9 +1,10 @@
 #include <cstdio>
 #include <cstdlib>
 
-#include "logging.hpp"
 #include <flags.hpp>
 
+#include "logging.hpp"
+
 using namespace std;
 
 int nop_log(const char *, va_list) { return 0; }
@@ -38,30 +39,19 @@ void cmdline_logging() {
     log_cb.ex = exit;
 }
 
-template <int type>
+#define LOG_BODY(prio) { \
-void log_handler(const char *fmt, ...) {
+    va_list argv;        \
-    va_list argv;
+    va_start(argv, fmt); \
-    va_start(argv, fmt);
+    log_cb.prio(fmt, argv); \
-    if constexpr (type == L_DEBUG) {
+    va_end(argv);        \
-        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);
-    }
-    va_end(argv);
 }
 
-template void log_handler<L_INFO>(const char *fmt, ...);
+// LTO will optimize out the NOP function
-template void log_handler<L_WARN>(const char *fmt, ...);
-template void log_handler<L_ERR>(const char *fmt, ...);
-
 #ifdef MAGISK_DEBUG
-template void log_handler<L_DEBUG>(const char *fmt, ...);
+void LOGD(const char *fmt, ...) { LOG_BODY(d) }
 #else
-// Strip debug logging for release builds
+void LOGD(const char *fmt, ...) {}
-template <> void log_handler<L_DEBUG>(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); log_cb.ex(1); }

native/jni/utils/logging.hpp

@@ -2,14 +2,6 @@
 
 #include <cerrno>
 #include <cstdarg>
-#include <cstring>
-
-enum {
-    L_DEBUG,
-    L_INFO,
-    L_WARN,
-    L_ERR
-};
 
 struct log_callback {
     int (*d)(const char* fmt, va_list ap);
@@ -21,10 +13,10 @@ struct log_callback {
 
 extern log_callback log_cb;
 
-#define LOGD(...) log_handler<L_DEBUG>(__VA_ARGS__)
+void LOGD(const char *fmt, ...) __printflike(1, 2);
-#define LOGI(...) log_handler<L_INFO>(__VA_ARGS__)
+void LOGI(const char *fmt, ...) __printflike(1, 2);
-#define LOGW(...) log_handler<L_WARN>(__VA_ARGS__)
+void LOGW(const char *fmt, ...) __printflike(1, 2);
-#define LOGE(...) log_handler<L_ERR>(__VA_ARGS__)
+void LOGE(const char *fmt, ...) __printflike(1, 2);
 #define PLOGE(fmt, args...) LOGE(fmt " failed with %d: %s\n", ##args, errno, std::strerror(errno))
 
 int nop_log(const char *, va_list);
@@ -32,6 +24,3 @@ void nop_ex(int);
 
 void no_logging();
 void cmdline_logging();
-
-template<int type>
-void log_handler(const char *fmt, ...) __printflike(1, 2);