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
>