[RFC BlueZ 0/2] Print bluetoothd messages in btmon

[RFC BlueZ 0/2] Print bluetoothd messages in btmon

[Vinicius Costa Gomes]

Hi,

It is very common when debugging issues, specially users' problems to
ask for btmon logs and the accompaining bluetoothd logs. And depending
on the issue, it takes some time to relate the HCI/MGMT commands to
bluetoothd messages that help narrow down the problem.

This is just a proof of concept, to know if this will be generally
helpful. And so, it needs some improvements: sending bluetoothd the USR2
signal so debug is enabled, color support and better formatting.


Cheers,


Vinicius Costa Gomes (2):
  monitor: Add stubs for monitoring bluetoothd's journal entries
  monitor: Add support for printing bluetoothd messages

 Makefile.tools    |   3 +-
 configure.ac      |   7 +++
 monitor/journal.c | 126 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 monitor/journal.h |  24 +++++++++++
 monitor/main.c    |  13 +++++-
 5 files changed, 171 insertions(+), 2 deletions(-)
 create mode 100644 monitor/journal.c
 create mode 100644 monitor/journal.h


--
1.8.5.3

[RFC BlueZ 1/2] monitor: Add stubs for monitoring bluetoothd's journal entries

[Vinicius Costa Gomes]

This will allow to have the output of bluetoothd in the same
place as the rest of the data that is being monitored, this
has the potencial to make it easier to know what bluetoothd
action caused which events.
---
 Makefile.tools    |  3 ++-
 configure.ac      |  7 +++++++
 monitor/journal.c | 33 +++++++++++++++++++++++++++++++++
 monitor/journal.h | 24 ++++++++++++++++++++++++
 monitor/main.c    | 13 ++++++++++++-
 5 files changed, 78 insertions(+), 2 deletions(-)
 create mode 100644 monitor/journal.c
 create mode 100644 monitor/journal.h

diff --git a/Makefile.tools b/Makefile.tools
index 52e49fb..42f7e4e 100644
--- a/Makefile.tools
+++ b/Makefile.tools
@@ -20,6 +20,7 @@ monitor_btmon_SOURCES = monitor/main.c monitor/bt.h \
 					monitor/btsnoop.h monitor/btsnoop.c \
 					monitor/ellisys.h monitor/ellisys.c \
 					monitor/control.h monitor/control.c \
+					monitor/journal.h monitor/journal.c \
 					monitor/packet.h monitor/packet.c \
 					monitor/vendor.h monitor/vendor.c \
 					monitor/lmp.h monitor/lmp.c \
@@ -32,7 +33,7 @@ monitor_btmon_SOURCES = monitor/main.c monitor/bt.h \
 					monitor/analyze.h monitor/analyze.c \
 					src/shared/util.h src/shared/util.c \
 					src/shared/queue.h src/shared/queue.c
-monitor_btmon_LDADD = lib/libbluetooth-internal.la @UDEV_LIBS@
+monitor_btmon_LDADD = lib/libbluetooth-internal.la @UDEV_LIBS@ @SYSTEMD_JOURNAL_LIBS@
 endif
 
 if EXPERIMENTAL
diff --git a/configure.ac b/configure.ac
index f607d7a..abd65cf 100644
--- a/configure.ac
+++ b/configure.ac
@@ -178,6 +178,13 @@ AC_ARG_ENABLE(systemd, AC_HELP_STRING([--disable-systemd],
 		[disable systemd integration]), [enable_systemd=${enableval}])
 AM_CONDITIONAL(SYSTEMD, test "${enable_systemd}" != "no")
 
+if (test "${enable_systemd}" != "no"); then
+	PKG_CHECK_MODULES(SYSTEMD_JOURNAL, libsystemd-journal, dummy=yes,
+				AC_MSG_ERROR(libsystemd-journal is required))
+	AC_SUBST(SYSTEMD_JOURNAL_CFLAGS)
+	AC_SUBST(SYSTEMD_JOURNAL_LIBS)
+fi
+
 AC_ARG_WITH([systemdsystemunitdir],
 			AC_HELP_STRING([--with-systemdsystemunitdir=DIR],
 			[path to systemd system unit directory]),
diff --git a/monitor/journal.c b/monitor/journal.c
new file mode 100644
index 0000000..ecc7dac
--- /dev/null
+++ b/monitor/journal.c
@@ -0,0 +1,33 @@
+/*
+ *
+ *  BlueZ - Bluetooth protocol stack for Linux
+ *
+ *  Copyright (C) 2014  Intel Corporation
+ *
+ *
+ *  This program is free software; you can redistribute it and/or modify
+ *  it under the terms of the GNU General Public License as published by
+ *  the Free Software Foundation; either version 2 of the License, or
+ *  (at your option) any later version.
+ *
+ *  This program is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *  GNU General Public License for more details.
+ *
+ *  You should have received a copy of the GNU General Public License
+ *  along with this program; if not, write to the Free Software
+ *  Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ *
+ */
+
+#include <errno.h>
+
+#include <systemd/sd-journal.h>
+
+#include "journal.h"
+
+int journal_monitor(void)
+{
+	return -ENOSYS;
+}
diff --git a/monitor/journal.h b/monitor/journal.h
new file mode 100644
index 0000000..895db02
--- /dev/null
+++ b/monitor/journal.h
@@ -0,0 +1,24 @@
+/*
+ *
+ *  BlueZ - Bluetooth protocol stack for Linux
+ *
+ *  Copyright (C) 2014  Intel Corporation
+ *
+ *
+ *  This program is free software; you can redistribute it and/or modify
+ *  it under the terms of the GNU General Public License as published by
+ *  the Free Software Foundation; either version 2 of the License, or
+ *  (at your option) any later version.
+ *
+ *  This program is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *  GNU General Public License for more details.
+ *
+ *  You should have received a copy of the GNU General Public License
+ *  along with this program; if not, write to the Free Software
+ *  Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
+ *
+ */
+
+int journal_monitor(void);
diff --git a/monitor/main.c b/monitor/main.c
index e7ee3e4..6fb1d28 100644
--- a/monitor/main.c
+++ b/monitor/main.c
@@ -38,6 +38,8 @@
 #include "analyze.h"
 #include "ellisys.h"
 #include "control.h"
+#include "btsnoop.h"
+#include "journal.h"
 
 static void signal_callback(int signum, void *user_data)
 {
@@ -64,6 +66,7 @@ static void usage(void)
 		"\t-T, --date             Show time and date information\n"
 		"\t-S, --sco              Dump SCO traffic\n"
 		"\t-E, --ellisys [ip]     Send Ellisys HCI Injection\n"
+		"\t-j, --journal          Show bluetoothd journal logs\n"
 		"\t-h, --help             Show help options\n");
 }
 
@@ -78,6 +81,7 @@ static const struct option main_options[] = {
 	{ "sco",     no_argument,	NULL, 'S' },
 	{ "ellisys", required_argument, NULL, 'E' },
 	{ "todo",    no_argument,       NULL, '#' },
+	{ "journal", no_argument,       NULL, 'j' },
 	{ "version", no_argument,       NULL, 'v' },
 	{ "help",    no_argument,       NULL, 'h' },
 	{ }
@@ -91,6 +95,7 @@ int main(int argc, char *argv[])
 	const char *analyze_path = NULL;
 	const char *ellisys_server = NULL;
 	unsigned short ellisys_port = 0;
+	bool journal = false;
 	const char *str;
 	sigset_t mask;
 
@@ -101,7 +106,7 @@ int main(int argc, char *argv[])
 	for (;;) {
 		int opt;
 
-		opt = getopt_long(argc, argv, "r:w:a:s:i:tTSE:vh",
+		opt = getopt_long(argc, argv, "r:w:a:s:i:tTSE:jvh",
 						main_options, NULL);
 		if (opt < 0)
 			break;
@@ -150,6 +155,9 @@ int main(int argc, char *argv[])
 			packet_todo();
 			lmp_todo();
 			return EXIT_SUCCESS;
+		case 'j':
+			journal = true;
+			break;
 		case 'v':
 			printf("%s\n", VERSION);
 			return EXIT_SUCCESS;
@@ -200,6 +208,9 @@ int main(int argc, char *argv[])
 	if (ellisys_server)
 		ellisys_enable(ellisys_server, ellisys_port);
 
+	if (journal)
+		journal_monitor();
+
 	if (control_tracing() < 0)
 		return EXIT_FAILURE;
 
-- 
1.8.5.3

[RFC BlueZ 2/2] monitor: Add support for printing bluetoothd messages

[Vinicius Costa Gomes]

In many cases when debugging bluetoothd behaviour, it is useful
to associate bluetooth debug outputs with HCI/MGMT commands and
events.
---
 monitor/journal.c | 95 ++++++++++++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 94 insertions(+), 1 deletion(-)

diff --git a/monitor/journal.c b/monitor/journal.c
index ecc7dac..1b04f02 100644
--- a/monitor/journal.c
+++ b/monitor/journal.c
@@ -22,12 +22,105 @@
  */
 
 #include <errno.h>
+#include <stdio.h>
 
 #include <systemd/sd-journal.h>
 
+#include "mainloop.h"
 #include "journal.h"
 
+static sd_journal *journal;
+
+static void journal_destroy(void *user_data)
+{
+	sd_journal *j = user_data;
+	sd_journal_close(j);
+}
+
+static void journal_event(int fd, uint32_t events, void *user_data)
+{
+	sd_journal *j = user_data;
+	const void *d;
+	const char *msg;
+	size_t l;
+	int err, prefix = strlen("MESSAGE=");
+
+	err = sd_journal_process(j);
+	if (err < 0) {
+		printf("Could not process journal: %s (%d)\n",
+				strerror(-err), err);
+		goto failed;
+	}
+
+	err = sd_journal_next(j);
+	if (err == 0) {
+		/* No more events in the journal, let's wait. */
+		return;
+	} else if (err < 0) {
+		printf("Failed to iterate to the next entry: %s (%d)\n",
+				strerror(-err), err);
+		goto failed;
+	}
+
+	err = sd_journal_get_data(j, "MESSAGE", &d, &l);
+	if (err < 0) {
+		printf("Could not get journal messages: %s (%d)",
+				strerror(-err), err);
+		goto failed;
+	}
+
+	msg = d;
+
+	/* TODO: better formatting, perhaps colors. */
+	/* msg is prefixed with 'MESSAGE=', remove it. */
+	printf("# %.*s\n", (int) l - prefix, msg + prefix);
+
+	return;
+
+failed:
+	mainloop_remove_fd(fd);
+}
+
 int journal_monitor(void)
 {
-	return -ENOSYS;
+	int err, events, fd;
+
+	err = sd_journal_open(&journal, SD_JOURNAL_SYSTEM |
+					SD_JOURNAL_RUNTIME_ONLY |
+					SD_JOURNAL_LOCAL_ONLY);
+	if (err < 0)
+		goto failed;
+
+	err = sd_journal_add_match(journal, "_SYSTEMD_UNIT=bluetooth.service", 0);
+	if (err < 0)
+		goto failed;
+
+	err = sd_journal_add_disjunction(journal);
+	if (err < 0)
+		goto failed;
+
+	err = sd_journal_seek_tail(journal);
+	if (err < 0)
+		goto failed;
+
+	fd = sd_journal_get_fd(journal);
+	if (fd < 0) {
+		err = fd;
+		goto failed;
+	}
+
+	events = sd_journal_get_events(journal);
+	if (events < 0) {
+		err = events;
+		goto failed;
+	}
+
+	return mainloop_add_fd(fd, events, journal_event, journal,
+				journal_destroy);
+
+failed:
+	printf("Failed to listen for journal messages: %s (%d)\n",
+			strerror(-err), err);
+	journal_destroy(journal);
+	return err;
 }
-- 
1.8.5.3

Re: [RFC BlueZ 0/2] Print bluetoothd messages in btmon

[Marcel Holtmann]

Hi Vinicius,

> It is very common when debugging issues, specially users' problems to
> ask for btmon logs and the accompaining bluetoothd logs. And depending
> on the issue, it takes some time to relate the HCI/MGMT commands to
> bluetoothd messages that help narrow down the problem.
> 
> This is just a proof of concept, to know if this will be generally
> helpful. And so, it needs some improvements: sending bluetoothd the USR2
> signal so debug is enabled, color support and better formatting.

so I am thinking to do this completely different.

I think that the btsnoop 2.0 format should get a section for notes/comments/logs where we can store text information. So you can actually interline HCI traffic with human readable comments. For example Apple is doing that with their Packet Logger. Obvious this is only useful if everything is in a single file that can be easily shared.

For this to work we need to read all the data from monitor interface of the kernel. Which means that the kernel also needs to have the debug/log output of bluetoothd. Meaning that bluetoothd would write the debug/logs into the kernel monitor interface and then they would be distributed to every btmon instance.

As a result bluetoothd would only log warnings, error and info messages to syslog/journal and all debug information should go back to the kernel.

Initially I was thinking just adding writing support monitor channel, but that is silly since it will turn on promiscuous mode. Something that is causing a bit of overhead on a production system. So we rather not do that. Maybe it would be better to assign a new HCI channel for bluetoothd logging data.

The one thing that is pretty obvious already is that we want to log per HCI index from bluetoothd. Which means we need to change the logging to be HCI controller aware. Without being HCI controller aware it is pretty much useless.

One interesting thing to think about is if we should tie enabling debug logs to the fact if btmon is running or not. And if we might allow btmon to configure the level of logs we want. It would be kinda cool if we can start btmon with -d ‘*audio*’ and then it magically gets all audio logs. Now it gets a bit funny with a kernel interface writing back into userspace to configure the logging level of a daemon.

I have been toying with the idea of having filters on btmon already and making the kernel just filter out packets so that userspace does not get woken up. I just never figured out the right API to do it.

Regards

Marcel

Re: [RFC BlueZ 0/2] Print bluetoothd messages in btmon

[Vinicius Costa Gomes]

Hi Marcel,

On 22:42 Tue 28 Jan, Marcel Holtmann wrote:
> Hi Vinicius,
>
> > It is very common when debugging issues, specially users' problems to
> > ask for btmon logs and the accompaining bluetoothd logs. And depending
> > on the issue, it takes some time to relate the HCI/MGMT commands to
> > bluetoothd messages that help narrow down the problem.
> >
> > This is just a proof of concept, to know if this will be generally
> > helpful. And so, it needs some improvements: sending bluetoothd the USR2
> > signal so debug is enabled, color support and better formatting.
>
> so I am thinking to do this completely different.
>
> I think that the btsnoop 2.0 format should get a section for notes/comments/logs where we can store text information. So you can actually interline HCI traffic with human readable comments. For example Apple is doing that with their Packet Logger. Obvious this is only useful if everything is in a single file that can be easily shared.
>
> For this to work we need to read all the data from monitor interface of the kernel. Which means that the kernel also needs to have the debug/log output of bluetoothd. Meaning that bluetoothd would write the debug/logs into the kernel monitor interface and then they would be distributed to every btmon instance.
>
> As a result bluetoothd would only log warnings, error and info messages to syslog/journal and all debug information should go back to the kernel.

Sounds great.

>
> Initially I was thinking just adding writing support monitor channel, but that is silly since it will turn on promiscuous mode. Something that is causing a bit of overhead on a production system. So we rather not do that. Maybe it would be better to assign a new HCI channel for bluetoothd logging data.
>
> The one thing that is pretty obvious already is that we want to log per HCI index from bluetoothd. Which means we need to change the logging to be HCI controller aware. Without being HCI controller aware it is pretty much useless.
>

I liked this. And having the logs HCI aware even makes sense if the logs go the usual places (syslog/journal). So it is a nice intermediate stage.

> One interesting thing to think about is if we should tie enabling debug logs to the fact if btmon is running or not. And if we might allow btmon to configure the level of logs we want. It would be kinda cool if we can start btmon with -d ‘*audio*’ and then it magically gets all audio logs. Now it gets a bit funny with a kernel interface writing back into userspace to configure the logging level of a daemon.

This gets complicated when we have multiple btmon's running. Interesting nonetheless.

>
> I have been toying with the idea of having filters on btmon already and making the kernel just filter out packets so that userspace does not get woken up. I just never figured out the right API to do it.
>
> Regards
>
> Marcel
>


Cheers,
--
Vinicius