debug: Add option to log to Linux tracing

Add the option (-T) to wpa_supplicant to log all debug messages into the
kernel tracing, allowing to aggregate kernel debugging with
wpa_supplicant debugging and recording all with trace-cmd.

Since tracing has relatively low overhead and can be filtered
afterwards, record all messages regardless of log level. However, it
will honor the -K option and not record key material by default.

Signed-hostap: Johannes Berg <johannes.berg@intel.com>

src/utils/wpa_debug.c

@@ -16,6 +16,18 @@
 static int wpa_debug_syslog = 0;
 #endif /* CONFIG_DEBUG_SYSLOG */
 
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <fcntl.h>
+#include <string.h>
+#include <stdio.h>
+
+static FILE *wpa_debug_tracing_file = NULL;
+
+#define WPAS_TRACE_PFX "wpas <%d>: "
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
+
 
 int wpa_debug_level = MSG_INFO;
 int wpa_debug_show_keys = 0;
@@ -107,6 +119,77 @@ static int syslog_priority(int level)
 #endif /* CONFIG_DEBUG_SYSLOG */
 
 
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+
+int wpa_debug_open_linux_tracing(void)
+{
+	int mounts, trace_fd;
+	char buf[4096] = {};
+	ssize_t buflen;
+	char *line, *tmp1, *path = NULL;
+
+	mounts = open("/proc/mounts", O_RDONLY);
+	if (mounts < 0) {
+		printf("no /proc/mounts\n");
+		return -1;
+	}
+
+	buflen = read(mounts, buf, sizeof(buf) - 1);
+	close(mounts);
+	if (buflen < 0) {
+		printf("failed to read /proc/mounts\n");
+		return -1;
+	}
+
+	line = strtok_r(buf, "\n", &tmp1);
+	while (line) {
+		char *tmp2, *tmp_path, *fstype;
+		/* "<dev> <mountpoint> <fs type> ..." */
+		strtok_r(line, " ", &tmp2);
+		tmp_path = strtok_r(NULL, " ", &tmp2);
+		fstype = strtok_r(NULL, " ", &tmp2);
+		if (strcmp(fstype, "debugfs") == 0) {
+			path = tmp_path;
+			break;
+		}
+
+		line = strtok_r(NULL, "\n", &tmp1);
+	}
+
+	if (path == NULL) {
+		printf("debugfs mountpoint not found\n");
+		return -1;
+	}
+
+	snprintf(buf, sizeof(buf) - 1, "%s/tracing/trace_marker", path);
+
+	trace_fd = open(buf, O_WRONLY);
+	if (trace_fd < 0) {
+		printf("failed to open trace_marker file\n");
+		return -1;
+	}
+	wpa_debug_tracing_file = fdopen(trace_fd, "w");
+	if (wpa_debug_tracing_file == NULL) {
+		close(trace_fd);
+		printf("failed to fdopen()\n");
+		return -1;
+	}
+
+	return 0;
+}
+
+
+void wpa_debug_close_linux_tracing(void)
+{
+	if (wpa_debug_tracing_file == NULL)
+		return;
+	fclose(wpa_debug_tracing_file);
+	wpa_debug_tracing_file = NULL;
+}
+
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
+
+
 /**
  * wpa_printf - conditional printf
  * @level: priority level (MSG_*) of the message
@@ -151,6 +234,17 @@ void wpa_printf(int level, const char *fmt, ...)
 #endif /* CONFIG_ANDROID_LOG */
 	}
 	va_end(ap);
+
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+	if (wpa_debug_tracing_file != NULL) {
+		va_start(ap, fmt);
+		fprintf(wpa_debug_tracing_file, WPAS_TRACE_PFX, level);
+		vfprintf(wpa_debug_tracing_file, fmt, ap);
+		fprintf(wpa_debug_tracing_file, "\n");
+		fflush(wpa_debug_tracing_file);
+		va_end(ap);
+	}
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
 }
 
 
@@ -158,6 +252,25 @@ static void _wpa_hexdump(int level, const char *title, const u8 *buf,
 			 size_t len, int show)
 {
 	size_t i;
+
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+	if (wpa_debug_tracing_file != NULL) {
+		fprintf(wpa_debug_tracing_file,
+			WPAS_TRACE_PFX "%s - hexdump(len=%lu):",
+			level, title, (unsigned long) len);
+		if (buf == NULL) {
+			fprintf(wpa_debug_tracing_file, " [NULL]\n");
+		} else if (!show) {
+			fprintf(wpa_debug_tracing_file, " [REMOVED]\n");
+		} else {
+			for (i = 0; i < len; i++)
+				fprintf(wpa_debug_tracing_file,
+					" %02x", buf[i]);
+		}
+		fflush(wpa_debug_tracing_file);
+	}
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
+
 	if (level < wpa_debug_level)
 		return;
 #ifdef CONFIG_ANDROID_LOG
@@ -281,6 +394,25 @@ static void _wpa_hexdump_ascii(int level, const char *title, const u8 *buf,
 	const u8 *pos = buf;
 	const size_t line_len = 16;
 
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+	if (wpa_debug_tracing_file != NULL) {
+		fprintf(wpa_debug_tracing_file,
+			WPAS_TRACE_PFX "%s - hexdump_ascii(len=%lu):",
+			level, title, (unsigned long) len);
+		if (buf == NULL) {
+			fprintf(wpa_debug_tracing_file, " [NULL]\n");
+		} else if (!show) {
+			fprintf(wpa_debug_tracing_file, " [REMOVED]\n");
+		} else {
+			/* can do ascii processing in userspace */
+			for (i = 0; i < len; i++)
+				fprintf(wpa_debug_tracing_file,
+					" %02x", buf[i]);
+		}
+		fflush(wpa_debug_tracing_file);
+	}
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
+
 	if (level < wpa_debug_level)
 		return;
 #ifdef CONFIG_ANDROID_LOG

src/utils/wpa_debug.h

@@ -255,6 +255,24 @@ static inline void wpa_debug_close_syslog(void)
 
 #endif /* CONFIG_DEBUG_SYSLOG */
 
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+
+int wpa_debug_open_linux_tracing(void);
+void wpa_debug_close_linux_tracing(void);
+
+#else /* CONFIG_DEBUG_LINUX_TRACING */
+
+static inline int wpa_debug_open_linux_tracing(void)
+{
+	return 0;
+}
+
+static inline void wpa_debug_close_linux_tracing(void)
+{
+}
+
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
+
 
 #ifdef EAPOL_TEST
 #define WPA_ASSERT(a)						       \

wpa_supplicant/Makefile

@@ -1273,6 +1273,10 @@ CFLAGS += -DLOG_HOSTAPD="$(CONFIG_DEBUG_SYSLOG_FACILITY)"
 endif
 endif
 
+ifdef CONFIG_DEBUG_LINUX_TRACING
+CFLAGS += -DCONFIG_DEBUG_LINUX_TRACING
+endif
+
 ifdef CONFIG_DEBUG_FILE
 CFLAGS += -DCONFIG_DEBUG_FILE
 endif

wpa_supplicant/defconfig

@@ -413,6 +413,12 @@ CONFIG_PEERKEY=y
 # Set syslog facility for debug messages
 #CONFIG_DEBUG_SYSLOG_FACILITY=LOG_DAEMON
 
+# Add support for sending all debug messages (regardless of debug verbosity)
+# to the Linux kernel tracing facility. This helps debug the entire stack by
+# making it easy to record everything happening from the driver up into the
+# same file, e.g., using trace-cmd.
+#CONFIG_DEBUG_LINUX_TRACING=y
+
 # Enable privilege separation (see README 'Privilege separation' for details)
 #CONFIG_PRIVSEP=y
 

wpa_supplicant/main.c

@@ -61,6 +61,10 @@ static void usage(void)
 #ifdef CONFIG_DEBUG_SYSLOG
 	printf("  -s = log output to syslog instead of stdout\n");
 #endif /* CONFIG_DEBUG_SYSLOG */
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+	printf("  -T = record to Linux tracing in addition to logging\n");
+	printf("       (records all messages regardless of debug verbosity)\n");
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
 	printf("  -t = include timestamp in debug messages\n"
 	       "  -h = show this help text\n"
 	       "  -L = show license (BSD)\n"
@@ -139,7 +143,8 @@ int main(int argc, char *argv[])
 	wpa_supplicant_fd_workaround();
 
 	for (;;) {
-		c = getopt(argc, argv, "b:Bc:C:D:de:f:g:hi:KLNo:O:p:P:qstuvW");
+		c = getopt(argc, argv,
+			   "b:Bc:C:D:de:f:g:hi:KLNo:O:p:P:qsTtuvW");
 		if (c < 0)
 			break;
 		switch (c) {
@@ -214,6 +219,11 @@ int main(int argc, char *argv[])
 			params.wpa_debug_syslog++;
 			break;
 #endif /* CONFIG_DEBUG_SYSLOG */
+#ifdef CONFIG_DEBUG_LINUX_TRACING
+		case 'T':
+			params.wpa_debug_tracing++;
+			break;
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
 		case 't':
 			params.wpa_debug_timestamp++;
 			break;

wpa_supplicant/wpa_supplicant.c

@@ -2875,6 +2875,14 @@ struct wpa_global * wpa_supplicant_init(struct wpa_params *params)
 	wpa_debug_open_file(params->wpa_debug_file_path);
 	if (params->wpa_debug_syslog)
 		wpa_debug_open_syslog();
+	if (params->wpa_debug_tracing) {
+		ret = wpa_debug_open_linux_tracing();
+		if (ret) {
+			wpa_printf(MSG_ERROR,
+				   "Failed to enable trace logging");
+			return NULL;
+		}
+	}
 
 	ret = eap_register_methods();
 	if (ret) {
@@ -3037,6 +3045,7 @@ void wpa_supplicant_deinit(struct wpa_global *global)
 	os_free(global);
 	wpa_debug_close_syslog();
 	wpa_debug_close_file();
+	wpa_debug_close_linux_tracing();
 }
 
 

wpa_supplicant/wpa_supplicant_i.h

@@ -160,6 +160,11 @@ struct wpa_params {
 	 */
 	int wpa_debug_syslog;
 
+	/**
+	 * wpa_debug_tracing - Enable log output through Linux tracing
+	 */
+	int wpa_debug_tracing;
+
 	/**
 	 * override_driver - Optional driver parameter override
 	 *