[RFC] nimble: add monitor protocol/interface + improve logs

[Andrzej Kaczmarek <an...@codecoup.pl>]

Hi,

I created a PR with implementation of monitor protocol/interface for
nimble. This is the same protocol as used by BlueZ and Zephyr for logging
which means we already have nice tools available for analysis.

PR: https://github.com/apache/incubator-mynewt-core/pull/362
Protocol:
https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/doc/btsnoop.txt

Basically, with this code you can get complete HCI traces, (partial) nimble
logging and console output over single UART or RTT in real
time.Unfortunately, at the moment it can be used easily on Linux where you
can capture and decode logs using btmon tool. It is then possible to open
saved logs in Wireshark on other platforms.

Some information on how to use it, let's start with configuration over UART:

CONSOLE_UART: 0
​BLE_MONITOR_UART: 1

​You will also most probably need to enable some other console, since UART
console is disabled. There are two options here:
- CONSOLE_RTT - bidirectional​ console over RTT
-
​ CONSOLE_BLE_MONITOR - output-only console over monitor​


Now the monitor interface is accessible over UART with default baudrate of
1M, use btmon to access it:

$ btmon -d /dev/ttyUSB0 --tty-speed 1000000 -p 8
Bluetooth monitor ver 5.45
--- /dev/ttyUSB0 opened ---

The major problem with UART is that it usually "produces" some unwanted
data e.g. during reset and this makes btmon stop recording. I guess the
most reliable way to use it is to break on main(), start btmon and then
continue.

But fortunately, it works much better over RTT:

BLE_MONITOR_RTT: 1

You can use any console with RTT, including RTT console since monitor uses
dedicated upstream buffer. The only problem here is that btmon can only
read data from TTY so I created small tool to redirect data from RTT to
PTY: https://github.com/codecoup/tools-rtt2pty/. There is no readme yet,
but with nRF5x and J-Link installed in default location it should be enough
to just launch it:

$ rtt2pty &
Connected to:
  J-Link OB-SAM3U128-V2-NordicSemi compiled Mar  2 2017 12:22:13
  S/N: 683111475
Searching for RTT control block...
Found 3 up-buffers.
Using buffer #1 (size=256)
PTY name is /dev/pts/3

As you can see I run it in the background - as long as you do not either
restart hw or load application which places RTT control block at different
place in RAM, you do not need to restart neither rtt2pty or connected btmon.

Now btmon:

$ btmon -d /dev/pts/3
Bluetooth monitor ver 5.45
--- /dev/pts/3 opened ---

And that's it for basic setup. Few more options (and default values) which
may come in handy:

BLE_MONITOR_UART_BAUDRATE: 1000000 -> UART baudrate (1M)
BLE_MONITOR_RTT_BUFFERED: 1 -> double buffering for RTT, see below
BLE_MONITOR_DEBUG: 0 -> redirect applicable nimble logs to monitor instead
of console, see below for additional info about nimble logging

The double buffering for RTT bears some explanation. For maximum
performance, monitor packets are written directly to RTT buffer in chunks.
This assumes that there is something on the other side to read the data
(like rtt2pty running in the background), as otherwise nimble will block
when RTT runs out of space waiting for someone to read the data - we cannot
just discard some chunk of data as it will break the protocol. To avoid
this an intermediate buffer is created (enabled by default) where complete
monitor packet is composed and then written at once or discarded. In worst
case, there will be just some dropped packets but nimble won't block. This
however requires extra space for this buffer and also extra copy to write
form intermediate buffer to RTT.

Another part of this PR are improvements in nimble logging. This is kind of
side-effect of using monitor interface, but I think an useful one.
Since logs in nimble are "composed" using multiple macro invocations the
were not really suitable to work with monitor which expects single line log
at once. I created set of new macros and helpers to have logs printf-ed in
single line along with function name by default. The old macros are still
in place since I updated only logs messages in crypto toolbox and GAP - se
respective commits for more explanation there.

Things still to do here:
- make buffers size configurable (for UART, RTT and logging) - they consume
some RAM now, it can be decreased at least in default configuration
- add statistics for dropped packets when using RTT double buffering
- update remaining logs to printf style

Oh, and in case you wonder how btmon trace with nimble stuff looks like,
here's an example from bleprph:
https://gist.github.com/andrzej-kaczmarek/118de10190192fbe76c4c2a2a7bf9299.

Comments?

Best regards,
Andrzej

Re: [RFC] nimble: add monitor protocol/interface + improve logs

[Andrzej Kaczmarek <an...@codecoup.pl>]

Hi all,

There were some comments about logging refactor stuff in original PR so I
extracted monitor protocol core implementation to separate PR as it does
not depend on it so can be merged first:
https://github.com/apache/mynewt-core/pull/372.
The old PR will be then used to deliver logging stuff once we agree on how
to do this properly.

Best regards,
Andrzej



On Thu, Jun 29, 2017 at 5:17 PM, Andrzej Kaczmarek <
andrzej.kaczmarek@codecoup.pl> wrote:

> Hi,
>
> I created a PR with implementation of monitor protocol/interface for
> nimble. This is the same protocol as used by BlueZ and Zephyr for logging
> which means we already have nice tools available for analysis.
>
> PR: https://github.com/apache/incubator-mynewt-core/pull/362
> Protocol: https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/
> doc/btsnoop.txt
>
> Basically, with this code you can get complete HCI traces, (partial)
> nimble logging and console output over single UART or RTT in real
> time.Unfortunately, at the moment it can be used easily on Linux where you
> can capture and decode logs using btmon tool. It is then possible to open
> saved logs in Wireshark on other platforms.
>
> Some information on how to use it, let's start with configuration over
> UART:
>
> CONSOLE_UART: 0
> ​BLE_MONITOR_UART: 1
>
> ​You will also most probably need to enable some other console, since UART
> console is disabled. There are two options here:
> - CONSOLE_RTT - bidirectional​ console over RTT
> -
> ​ CONSOLE_BLE_MONITOR - output-only console over monitor​
>
>
> Now the monitor interface is accessible over UART with default baudrate of
> 1M, use btmon to access it:
>
> $ btmon -d /dev/ttyUSB0 --tty-speed 1000000 -p 8
> Bluetooth monitor ver 5.45
> --- /dev/ttyUSB0 opened ---
>
> The major problem with UART is that it usually "produces" some unwanted
> data e.g. during reset and this makes btmon stop recording. I guess the
> most reliable way to use it is to break on main(), start btmon and then
> continue.
>
> But fortunately, it works much better over RTT:
>
> BLE_MONITOR_RTT: 1
>
> You can use any console with RTT, including RTT console since monitor uses
> dedicated upstream buffer. The only problem here is that btmon can only
> read data from TTY so I created small tool to redirect data from RTT to
> PTY: https://github.com/codecoup/tools-rtt2pty/. There is no readme yet,
> but with nRF5x and J-Link installed in default location it should be enough
> to just launch it:
>
> $ rtt2pty &
> Connected to:
>   J-Link OB-SAM3U128-V2-NordicSemi compiled Mar  2 2017 12:22:13
>   S/N: 683111475
> Searching for RTT control block...
> Found 3 up-buffers.
> Using buffer #1 (size=256)
> PTY name is /dev/pts/3
>
> As you can see I run it in the background - as long as you do not either
> restart hw or load application which places RTT control block at different
> place in RAM, you do not need to restart neither rtt2pty or connected btmon.
>
> Now btmon:
>
> $ btmon -d /dev/pts/3
> Bluetooth monitor ver 5.45
> --- /dev/pts/3 opened ---
>
> And that's it for basic setup. Few more options (and default values) which
> may come in handy:
>
> BLE_MONITOR_UART_BAUDRATE: 1000000 -> UART baudrate (1M)
> BLE_MONITOR_RTT_BUFFERED: 1 -> double buffering for RTT, see below
> BLE_MONITOR_DEBUG: 0 -> redirect applicable nimble logs to monitor instead
> of console, see below for additional info about nimble logging
>
> The double buffering for RTT bears some explanation. For maximum
> performance, monitor packets are written directly to RTT buffer in chunks.
> This assumes that there is something on the other side to read the data
> (like rtt2pty running in the background), as otherwise nimble will block
> when RTT runs out of space waiting for someone to read the data - we cannot
> just discard some chunk of data as it will break the protocol. To avoid
> this an intermediate buffer is created (enabled by default) where complete
> monitor packet is composed and then written at once or discarded. In worst
> case, there will be just some dropped packets but nimble won't block. This
> however requires extra space for this buffer and also extra copy to write
> form intermediate buffer to RTT.
>
> Another part of this PR are improvements in nimble logging. This is kind
> of side-effect of using monitor interface, but I think an useful one.
> Since logs in nimble are "composed" using multiple macro invocations the
> were not really suitable to work with monitor which expects single line log
> at once. I created set of new macros and helpers to have logs printf-ed in
> single line along with function name by default. The old macros are still
> in place since I updated only logs messages in crypto toolbox and GAP - se
> respective commits for more explanation there.
>
> Things still to do here:
> - make buffers size configurable (for UART, RTT and logging) - they
> consume some RAM now, it can be decreased at least in default configuration
> - add statistics for dropped packets when using RTT double buffering
> - update remaining logs to printf style
>
> Oh, and in case you wonder how btmon trace with nimble stuff looks like,
> here's an example from bleprph: https://gist.github.com/andrzej-kaczmarek/
> 118de10190192fbe76c4c2a2a7bf9299.
>
> Comments?
>
> Best regards,
> Andrzej
>