Better logging system

Use C++ magic to strip out debug logs at compile time

build.py

@@ -299,7 +299,7 @@ def build_binary(args):
 
     header('* Building binaries: ' + ' '.join(args.target))
 
-    os.utime(op.join('native', 'jni', 'include', 'flags.h'))
+    os.utime(op.join('native', 'jni', 'include', 'flags.hpp'))
 
     # Basic flags
     global base_flags

native/jni/core/daemon.cpp

@@ -13,7 +13,7 @@
 #include <selinux.hpp>
 #include <db.hpp>
 #include <resetprop.hpp>
-#include <flags.h>
+#include <flags.hpp>
 
 using namespace std;
 
@@ -129,16 +129,14 @@ shortcut:
 	close(client);
 }
 
+#define vlog __android_log_vprint
+
 static void android_logging() {
 	static constexpr char TAG[] = "Magisk";
-#ifdef MAGISK_DEBUG
+	log_cb.d = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_DEBUG, TAG, fmt, ap); };
-	log_cb.d = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_DEBUG, TAG, fmt, ap); };
+	log_cb.i = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_INFO, TAG, fmt, ap); };
-#else
+	log_cb.w = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_WARN, TAG, fmt, ap); };
-	log_cb.d = nop_log;
+	log_cb.e = [](auto fmt, auto ap){ return vlog(ANDROID_LOG_ERROR, TAG, fmt, ap); };
-#endif
-	log_cb.i = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_INFO, TAG, fmt, ap); };
-	log_cb.w = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_WARN, TAG, fmt, ap); };
-	log_cb.e = [](auto fmt, auto ap){ return __android_log_vprint(ANDROID_LOG_ERROR, TAG, fmt, ap); };
 	log_cb.ex = nop_ex;
 }
 

native/jni/core/magisk.cpp

@@ -1,21 +1,17 @@
 #include <sys/mount.h>
-#include <stdlib.h>
-#include <stdio.h>
-#include <unistd.h>
 #include <libgen.h>
-#include <string.h>
 
 #include <utils.hpp>
 #include <magisk.hpp>
 #include <daemon.hpp>
 #include <selinux.hpp>
-#include <flags.h>
+#include <flags.hpp>
 
-using namespace std::literals;
+using namespace std;
 
 [[noreturn]] static void usage() {
 	fprintf(stderr,
-NAME_WITH_VER(Magisk) R"EOF( multi-call binary
+R"EOF(Magisk - Multi-purpose Utility
 
 Usage: magisk [applet [arguments]...]
    or: magisk [options]...

native/jni/core/module.cpp

@@ -7,15 +7,10 @@
 #include <selinux.hpp>
 #include <daemon.hpp>
 #include <resetprop.hpp>
-#include <flags.h>
 
 using namespace std;
 
-#ifdef MAGISK_DEBUG
 #define VLOGI(tag, from, to) LOGI("%-8s: %s <- %s\n", tag, to, from)
-#else
-#define VLOGI(tag, from, to) LOGI("%-8s: %s\n", tag, to)
-#endif
 
 #define TYPE_MIRROR  (1 << 0)    /* mount from mirror */
 #define TYPE_INTER   (1 << 1)    /* intermediate node */

native/jni/init/getinfo.cpp

@@ -87,18 +87,58 @@ static bool check_key_combo() {
 	return false;
 }
 
-void load_kernel_info(cmdline *cmd) {
+static FILE *kmsg;
-	// Communicate with kernel using procfs and sysfs
+static char kmsg_buf[4096];
-	xmkdir("/proc", 0755);
+static int vprintk(const char *fmt, va_list ap) {
-	xmount("proc", "/proc", "proc", 0, nullptr);
+	vsnprintf(kmsg_buf + 12, sizeof(kmsg_buf) - 12, fmt, ap);
-	xmkdir("/sys", 0755);
+	return fprintf(kmsg, "%s", kmsg_buf);
-	xmount("sysfs", "/sys", "sysfs", 0, nullptr);
+}
+void setup_klog() {
+	// Shut down first 3 fds
+	int fd;
+	if (access("/dev/null", W_OK) == 0) {
+		fd = xopen("/dev/null", O_RDWR | O_CLOEXEC);
+	} else {
+		mknod("/null", S_IFCHR | 0666, makedev(1, 3));
+		fd = xopen("/null", O_RDWR | O_CLOEXEC);
+		unlink("/null");
+	}
+	xdup3(fd, STDIN_FILENO, O_CLOEXEC);
+	xdup3(fd, STDOUT_FILENO, O_CLOEXEC);
+	xdup3(fd, STDERR_FILENO, O_CLOEXEC);
+	if (fd > STDERR_FILENO)
+		close(fd);
+
+	if (access("/dev/kmsg", W_OK) == 0) {
+		fd = xopen("/dev/kmsg", O_WRONLY | O_CLOEXEC);
+	} else {
+		mknod("/kmsg", S_IFCHR | 0666, makedev(1, 11));
+		fd = xopen("/kmsg", O_WRONLY | O_CLOEXEC);
+		unlink("/kmsg");
+	}
+
+	kmsg = fdopen(fd, "w");
+	setbuf(kmsg, nullptr);
+	log_cb.d = log_cb.i = log_cb.w = log_cb.e = vprintk;
+	log_cb.ex = nop_ex;
+	strcpy(kmsg_buf, "magiskinit: ");
 
 	// Disable kmsg rate limiting
 	if (FILE *rate = fopen("/proc/sys/kernel/printk_devkmsg", "w")) {
 		fprintf(rate, "on\n");
 		fclose(rate);
 	}
+}
+
+void load_kernel_info(cmdline *cmd) {
+	// Get kernel data using procfs and sysfs
+	xmkdir("/proc", 0755);
+	xmount("proc", "/proc", "proc", 0, nullptr);
+	xmkdir("/sys", 0755);
+	xmount("sysfs", "/sys", "sysfs", 0, nullptr);
+
+	// Log to kernel
+	setup_klog();
 
 	parse_cmdline([&](auto key, auto value) -> void {
 		if (key == "androidboot.slot_suffix") {

native/jni/init/init.cpp

@@ -1,8 +1,6 @@
 #include <sys/stat.h>
 #include <sys/types.h>
 #include <sys/sysmacros.h>
-#include <stdio.h>
-#include <string.h>
 #include <fcntl.h>
 #include <libgen.h>
 #include <vector>
@@ -11,7 +9,6 @@
 #include <magisk.hpp>
 #include <cpio.hpp>
 #include <utils.hpp>
-#include <flags.h>
 
 #include "binaries.h"
 #ifdef USE_64BIT
@@ -27,47 +24,6 @@ using namespace std;
 constexpr int (*init_applet_main[])(int, char *[]) =
 		{ magiskpolicy_main, magiskpolicy_main, nullptr };
 
-#ifdef MAGISK_DEBUG
-static FILE *kmsg;
-static char kmsg_buf[4096];
-static int vprintk(const char *fmt, va_list ap) {
-	vsnprintf(kmsg_buf + 12, sizeof(kmsg_buf) - 12, fmt, ap);
-	return fprintf(kmsg, "%s", kmsg_buf);
-}
-void setup_klog() {
-	// Shut down first 3 fds
-	int fd;
-	if (access("/dev/null", W_OK) == 0) {
-		fd = xopen("/dev/null", O_RDWR | O_CLOEXEC);
-	} else {
-		mknod("/null", S_IFCHR | 0666, makedev(1, 3));
-		fd = xopen("/null", O_RDWR | O_CLOEXEC);
-		unlink("/null");
-	}
-	xdup3(fd, STDIN_FILENO, O_CLOEXEC);
-	xdup3(fd, STDOUT_FILENO, O_CLOEXEC);
-	xdup3(fd, STDERR_FILENO, O_CLOEXEC);
-	if (fd > STDERR_FILENO)
-		close(fd);
-
-	if (access("/dev/kmsg", W_OK) == 0) {
-		fd = xopen("/dev/kmsg", O_WRONLY | O_CLOEXEC);
-	} else {
-		mknod("/kmsg", S_IFCHR | 0666, makedev(1, 11));
-		fd = xopen("/kmsg", O_WRONLY | O_CLOEXEC);
-		unlink("/kmsg");
-	}
-
-	kmsg = fdopen(fd, "w");
-	setbuf(kmsg, nullptr);
-	log_cb.d = log_cb.i = log_cb.w = log_cb.e = vprintk;
-	log_cb.ex = nop_ex;
-	strcpy(kmsg_buf, "magiskinit: ");
-}
-#else
-void setup_klog() {}
-#endif
-
 static bool unxz(int fd, const uint8_t *buf, size_t size) {
 	uint8_t out[8192];
 	xz_crc32_init();
@@ -193,7 +149,7 @@ int main(int argc, char *argv[]) {
 			return (*init_applet_main[i])(argc, argv);
 	}
 
-#ifdef MAGISK_DEBUG
+#if 0
 	if (getenv("INIT_TEST") != nullptr)
 		return test_main(argc, argv);
 #endif
@@ -207,12 +163,12 @@ int main(int argc, char *argv[]) {
 
 	if (getpid() != 1)
 		return 1;
-	setup_klog();
 
 	BaseInit *init;
 	cmdline cmd{};
 
 	if (argc > 1 && argv[1] == "selinux_setup"sv) {
+		setup_klog();
 		init = new SecondStageInit(argv);
 	} else {
 		// This will also mount /sys and /proc

native/jni/magiskboot/main.cpp

@@ -1,13 +1,12 @@
-#include <stdlib.h>
+#include <cstdlib>
-#include <stdio.h>
+#include <cstdio>
-#include <string.h>
+#include <cstring>
 #include <unistd.h>
 #include <sys/mman.h>
 
 #include <mincrypt/sha.h>
 #include <logging.hpp>
 #include <utils.hpp>
-#include <flags.h>
 
 #include "magiskboot.hpp"
 #include "compress.hpp"
@@ -16,7 +15,7 @@ using namespace std;
 
 static void usage(char *arg0) {
 	fprintf(stderr,
-NAME_WITH_VER(MagiskBoot) R"EOF( - Boot Image Modification Tool
+R"EOF(MagiskBoot - Boot Image Modification Tool
 
 Usage: %s <action> [args...]
 

native/jni/magiskhide/magiskhide.cpp

@@ -10,7 +10,6 @@
 
 #include <daemon.hpp>
 #include <utils.hpp>
-#include <flags.h>
 
 #include "magiskhide.hpp"
 
@@ -18,7 +17,7 @@ using namespace std::literals;
 
 [[noreturn]] static void usage(char *arg0) {
 	fprintf(stderr,
-		NAME_WITH_VER(MagiskHide) "\n\n"
+		"MagiskHide - Hide Config CLI\n\n"
 		"Usage: %s [action [arguments...] ]\n\n"
 		"Actions:\n"
   		"   status          Return the status of magiskhide\n"
@@ -106,7 +105,7 @@ int magiskhide_main(int argc, char *argv[]) {
 		execvp(argv[2], argv + 2);
 		exit(1);
 	}
-#ifdef MAGISK_DEBUG
+#if 0
 	else if (opt == "test"sv)
 		test_proc_monitor();
 #endif

native/jni/magiskpolicy/magiskpolicy.cpp

@@ -1,9 +1,5 @@
-#include <stdio.h>
-#include <limits.h>
-
 #include <logging.hpp>
 #include <utils.hpp>
-#include <flags.h>
 #include <magiskpolicy.hpp>
 
 #include "sepolicy.hpp"
@@ -12,7 +8,7 @@ using namespace std::literals;
 
 [[noreturn]] static void usage(char *arg0) {
 	fprintf(stderr,
-NAME_WITH_VER(MagiskPolicy) R"EOF(
+R"EOF(MagiskPolicy - Sepolicy Patch Tool
 
 Usage: %s [--options...] [policy statements...]
 

native/jni/magiskpolicy/rules.cpp

@@ -1,7 +1,6 @@
 #include <initializer_list>
 
 #include <logging.hpp>
-#include <flags.h>
 #include <magiskpolicy.hpp>
 
 #include "sepolicy.hpp"

native/jni/resetprop/resetprop.cpp

@@ -6,7 +6,6 @@
 #include <logging.hpp>
 #include <resetprop.hpp>
 #include <utils.hpp>
-#include <flags.h>
 
 #define _REALLY_INCLUDE_SYS__SYSTEM_PROPERTIES_H_
 #include <_system_properties.h>
@@ -22,7 +21,7 @@ static int (*system_property_set)(const char*, const char*);
 
 [[noreturn]] static void usage(char* arg0) {
 	fprintf(stderr,
-NAME_WITH_VER(resetprop) R"EOF(" - System Props Modification Tool
+R"EOF("resetprop - System Props Modification Tool
 
 Usage: %s [flags] [options...]
 

native/jni/su/su.cpp

@@ -23,7 +23,7 @@
 
 #include <daemon.hpp>
 #include <utils.hpp>
-#include <flags.h>
+#include <flags.hpp>
 
 #include "su.hpp"
 #include "pts.hpp"
@@ -34,7 +34,7 @@ static void usage(int status) {
 	FILE *stream = (status == EXIT_SUCCESS) ? stdout : stderr;
 
 	fprintf(stream,
-	NAME_WITH_VER(MagiskSU) "\n\n"
+	"MagiskSU\n\n"
 	"Usage: su [options] [-] [user [argument...]]\n\n"
 	"Options:\n"
 	"  -c, --command COMMAND         pass COMMAND to the invoked shell\n"

native/jni/utils/include/logging.hpp

@@ -1,17 +1,15 @@
 #pragma once
 
-#include <errno.h>
+#include <cerrno>
-#include <stdarg.h>
+#include <cstdarg>
-#include <string.h>
+#include <cstring>
 
-__BEGIN_DECLS
+enum {
-
-typedef enum {
 	L_DEBUG,
 	L_INFO,
 	L_WARN,
 	L_ERR
-} log_type;
+};
 
 struct log_callback {
 	int (*d)(const char* fmt, va_list ap);
@@ -21,20 +19,19 @@ struct log_callback {
 	void (*ex)(int code);
 };
 
-extern struct log_callback log_cb;
+extern log_callback log_cb;
 
-#define LOGD(...) log_handler(L_DEBUG, __VA_ARGS__)
+#define LOGD(...) log_handler<L_DEBUG>(__VA_ARGS__)
-#define LOGI(...) log_handler(L_INFO, __VA_ARGS__)
+#define LOGI(...) log_handler<L_INFO>(__VA_ARGS__)
-#define LOGW(...) log_handler(L_WARN, __VA_ARGS__)
+#define LOGW(...) log_handler<L_WARN>(__VA_ARGS__)
-#define LOGE(...) log_handler(L_ERR, __VA_ARGS__)
+#define LOGE(...) log_handler<L_ERR>(__VA_ARGS__)
-#define PLOGE(fmt, args...) LOGE(fmt " failed with %d: %s\n", ##args, errno, strerror(errno))
+#define PLOGE(fmt, args...) LOGE(fmt " failed with %d: %s\n", ##args, errno, std::strerror(errno))
 
-int nop_log(const char *fmt, va_list ap);
+int nop_log(const char *, va_list);
-void nop_ex(int i);
+void nop_ex(int);
 
 void no_logging();
 void cmdline_logging();
 
-int log_handler(log_type t, const char *fmt, ...);
+template<int type>
-
+void log_handler(const char *fmt, ...) __printflike(1, 2);
-__END_DECLS

native/jni/utils/logging.cpp

@@ -1,15 +1,16 @@
-#include <stdio.h>
+#include <cstdio>
-#include <stdlib.h>
+#include <cstdlib>
 
 #include <logging.hpp>
+#include <flags.hpp>
 
-int nop_log(const char *fmt, va_list ap) {
+using namespace std;
-	return 0;
-}
 
-void nop_ex(int i) {}
+int nop_log(const char *, va_list) { return 0; }
 
-struct log_callback log_cb = {
+void nop_ex(int) {}
+
+log_callback log_cb = {
 	.d = nop_log,
 	.i = nop_log,
 	.w = nop_log,
@@ -25,37 +26,42 @@ void no_logging() {
 	log_cb.ex = nop_ex;
 }
 
-static int vprinte(const char *fmt, va_list ap) {
+static int vprintfe(const char *fmt, va_list ap) {
 	return vfprintf(stderr, fmt, ap);
 }
 
 void cmdline_logging() {
-	log_cb.d = vprinte;
+	log_cb.d = vprintfe;
 	log_cb.i = vprintf;
-	log_cb.w = vprinte;
+	log_cb.w = vprintfe;
-	log_cb.e = vprinte;
+	log_cb.e = vprintfe;
 	log_cb.ex = exit;
 }
 
-int log_handler(log_type t, const char *fmt, ...) {
+template <int type>
+void log_handler(const char *fmt, ...) {
 	va_list argv;
-	int ret = 0;
 	va_start(argv, fmt);
-	switch (t) {
+	if constexpr (type == L_DEBUG) {
-	case L_DEBUG:
+		log_cb.d(fmt, argv);
-		ret = log_cb.d(fmt, argv);
+	} else if constexpr (type == L_INFO) {
-		break;
+		log_cb.i(fmt, argv);
-	case L_INFO:
+	} else if constexpr (type == L_WARN) {
-		ret = log_cb.i(fmt, argv);
+		log_cb.w(fmt, argv);
-		break;
+	} else if constexpr (type == L_ERR) {
-	case L_WARN:
+		log_cb.e(fmt, argv);
-		ret = log_cb.w(fmt, argv);
-		break;
-	case L_ERR:
-		ret = log_cb.e(fmt, argv);
 		log_cb.ex(1);
-		break;
 	}
 	va_end(argv);
-	return ret;
 }
+
+template void log_handler<L_INFO>(const char *fmt, ...);
+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, ...);
+#else
+// Strip debug logging for release builds
+template <> void log_handler<L_DEBUG>(const char *fmt, ...) {}
+#endif

native/jni/utils/xwrap.cpp

@@ -84,7 +84,7 @@ ssize_t xread(int fd, void *buf, size_t count) {
 ssize_t xxread(int fd, void *buf, size_t count) {
 	int ret = read(fd, buf, count);
 	if (count != ret) {
-		PLOGE("read (%d != %d)", count, ret);
+		PLOGE("read (%zu != %d)", count, ret);
 	}
 	return ret;
 }