Patchwork debug: add option to log to tracing

login
register
mail settings
Submitter Johannes Berg
Date March 12, 2012, 1:43 p.m.
Message ID <1331559830.3496.7.camel@jlt3.sipsolutions.net>
Download mbox | patch
Permalink /patch/146100/
State Accepted
Commit 4f68895e923fea3c5aefcca0ae75aa06ac698b9c
Headers show

Comments

Johannes Berg - March 12, 2012, 1:43 p.m.
From: Johannes Berg <johannes.berg@intel.com>

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 is has relatively low overhead
and can be filtered afterwards, record all
messages regardless of log level. However,
it will honour the -K option and not record
key material by default.

Signed-hostap: Johannes Berg <johannes.berg@intel.com>
---
 src/utils/wpa_debug.c             |  130 +++++++++++++++++++++++++++++++++++++
 src/utils/wpa_debug.h             |   13 ++++
 wpa_supplicant/Makefile           |    4 +
 wpa_supplicant/defconfig          |    6 ++
 wpa_supplicant/main.c             |   11 +++-
 wpa_supplicant/wpa_supplicant.c   |    9 +++
 wpa_supplicant/wpa_supplicant_i.h |    5 ++
 7 files changed, 177 insertions(+), 1 deletions(-)
Jouni Malinen - March 31, 2012, 11:02 a.m.
On Mon, Mar 12, 2012 at 02:43:50PM +0100, Johannes Berg wrote:
> 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 is has relatively low overhead
> and can be filtered afterwards, record all
> messages regardless of log level. However,
> it will honour the -K option and not record
> key material by default.

Thanks! Applied.

> diff --git a/src/utils/wpa_debug.c b/src/utils/wpa_debug.c
> @@ -106,6 +118,72 @@ static int syslog_priority(int level)
> +int wpa_debug_open_linux_tracing(void)

> +	line = strtok_r(buf, "\n", &tmp1);
> +	if (line) do {
> +		char *tmp2, *tmp_path, *fstype;
> +
> +		/* "<dev> <mountpoint> <fs type> ..." */
> +		strtok_r(line, " ", &tmp2);

gcc was not happy about this construction for some reason.. It seemed to
think that line could be NULL here and warned about tmp2 not having been
initialized.

> +	} while ((line = strtok_r(NULL, "\n", &tmp1)));

I converted this somewhat strange if-do-while loop into a simpler while
loop which is apparently easier for gcc (and me, too, for that matter)
to understand.

> @@ -281,6 +388,29 @@ static void _wpa_hexdump_ascii(int level, const char *title, const u8 *buf,
> +	if (wpa_debug_tracing_file != NULL) {
> +		size_t orig_len = len;
> +
> +		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);
> +
> +		len = orig_len;
> +	}

I can't see where the len variable would be changed here, so I dropped
the orig_len save-and-restore.

Patch

diff --git a/src/utils/wpa_debug.c b/src/utils/wpa_debug.c
index 858a97c..2777121 100644
--- a/src/utils/wpa_debug.c
+++ b/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;
@@ -106,6 +118,72 @@  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);
+	if (line) do {
+		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;
+		}
+	} while ((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
@@ -151,6 +229,16 @@  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 +246,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 +388,29 @@  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) {
+		size_t orig_len = len;
+
+		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);
+
+		len = orig_len;
+	}
+#endif /* CONFIG_DEBUG_LINUX_TRACING */
+
 	if (level < wpa_debug_level)
 		return;
 #ifdef CONFIG_ANDROID_LOG
diff --git a/src/utils/wpa_debug.h b/src/utils/wpa_debug.h
index c79907a..2aac1c5 100644
--- a/src/utils/wpa_debug.h
+++ b/src/utils/wpa_debug.h
@@ -255,6 +255,19 @@  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
+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)						       \
diff --git a/wpa_supplicant/Makefile b/wpa_supplicant/Makefile
index a976098..b3a9d55 100644
--- a/wpa_supplicant/Makefile
+++ b/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
diff --git a/wpa_supplicant/defconfig b/wpa_supplicant/defconfig
index 480bc64..2668e6d 100644
--- a/wpa_supplicant/defconfig
+++ b/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
 
diff --git a/wpa_supplicant/main.c b/wpa_supplicant/main.c
index c124ca2..5ccdf3c 100644
--- a/wpa_supplicant/main.c
+++ b/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,7 @@  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 +218,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;
diff --git a/wpa_supplicant/wpa_supplicant.c b/wpa_supplicant/wpa_supplicant.c
index 36074d5..87de57d 100644
--- a/wpa_supplicant/wpa_supplicant.c
+++ b/wpa_supplicant/wpa_supplicant.c
@@ -2874,6 +2874,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\n");
+			return NULL;
+		}
+	}
 
 	ret = eap_register_methods();
 	if (ret) {
@@ -3036,6 +3044,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();
 }
 
 
diff --git a/wpa_supplicant/wpa_supplicant_i.h b/wpa_supplicant/wpa_supplicant_i.h
index 0ba1935..e2e0aed 100644
--- a/wpa_supplicant/wpa_supplicant_i.h
+++ b/wpa_supplicant/wpa_supplicant_i.h
@@ -161,6 +161,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
 	 *
 	 * This parameter can be used to override the driver parameter in