Logging: Assert with LOG_IMMEDIATE

[Vudentz]

uart:~$ bt init
ASSERTION FAIL [out_ctx->control_block->offset <= out_ctx->size] @ ZEPHYR_BASE/subsys/logging/log_output.c:101

Build tests/bluetooth/shell

1. mkdir build; cd build
2. cmake -DBOARD=qemu_x86
3. make
4. See error

Looks like this got introduced by 2192499 since it is only reproducible with LOG_IMMEDIATE which is now selected by TEST_LOGGING_DEFAULTS.

[jfischer-no]

similar to #19238

[andrewboie]

make[1]: *** No rule to make target 'ell/util.c', needed by 'ell/util.lo'.  Stop.
Makefile:3513: recipe for target 'all' failed
make: *** [all] Error 2

I'm having trouble reproducing this, as running this sample requires a working bluez installation, and I get the above build error in bluez git master when I try to build it for my Ubuntu 18.04 machine (the distro bluez packages do not provide btproxy). Do you have a working ref or tag in upstream bluez that builds?

At any rate, I just enabled immediate mode logging for tests, I'm not as deeply familiar with its internal implementation as some others (cc @nordic-krch )

@Vudentz can you give #19322 a try? It changes the default for tests from logging with immediate mode, to a thin wrapper on top of printk. Even if that goes in I would leave this open though.

An immediate workaround would be to set CONFIG_TEST_LOGGING_DEFAULTS=n in the various prj.conf in tests/bluetooth/shell.

[nordic-krch]

An immediate workaround would be to set CONFIG_TEST_LOGGING_DEFAULTS=n in the various prj.conf in tests/bluetooth/shell.

I looks like setting immediate logging for tests (and minimal logging in future #19322) has consequences:

• thread stack usage increase since logs are formatted in the caller context
• some tests on HW may stop working if logs are present in the interrupts with timing requirements (e.g. follwing log message [00:00:00.014,373] <dbg> usb_descriptor.usb_get_device_descriptor: __usb_descriptor_end 0x200033d9 processing and printing over uart takes 9ms on nrf52840)

@andrewboie what was the reason for switching to immediate mode?

[andrewboie]

@andrewboie what was the reason for switching to immediate mode?

Because otherwise the log buffers overflow if anything more than a few messages are printed at a time. This is especially noticeable for any test which generates a fatal error (try tests/kernel/fatal) Seriously, the defaults right now are unusable. We could spend forever trying to trade-off between not losing any messages and how much buffer space we can get away with...not interested in going down this rabbit hole

thread stack usage increase since logs are formatted in the caller context

Just fix these issues if they come up IMO. Got anything specific other than this one bluetooth test? This one slipped through because CI never actually runs it due to it requiring a special environment to run in QEMU

some tests on HW may stop working if logs are present in the interrupts with timing requirements (e.g. follwing log message [00:00:00.014,373] usb_descriptor.usb_get_device_descriptor: __usb_descriptor_end 0x200033d9 processing and printing over uart takes 9ms on nrf52840)

@nordic-krch The logging defaults suppress DBG messages (or they should) so what's the problem here?? Let's not overstate the case!

The alternative is that I revert all the changes which cause fatal error handling to integrate with the logger, and delete CONFIG_TEST_LOGGING_DEFAULTS. We can go back to disabling LOG everywhere, but wouldn't we like to get rid of all the use of printk in the kernel and just standardize on one API for emitting diagnostic messages?

[ioannisg]

@nordic-krch what's the status of this bug?

[nordic-krch]

I believe it is fixed but have no bluetooth tools to run it. @Vudentz can you check?

[ioannisg]

Thanks @nordic-krch . In that case we rely on @Vudentz to provide some feedback; please, do so we might be able to close this Medium Priority issue for Zephyr v2.1.

[jhedberg]

@Vudentz could you please re-check if this issue still exists? It's marked as medium so it'd be good to close it if it's already fixed upstream.

[carlescufi]

I just tested this now:

carles@zephyr-nrf ~/src/zephyr/zephyr (master *)
$ cat build/zephyr/.config | grep IMMEDIATE
CONFIG_LOG_IMMEDIATE=y
# CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT is not set

carles@zephyr-nrf ~/src/zephyr/zephyr (master *)
$ west build -t run
-- west build: build configuration:
       source directory: /home/carles/src/zephyr/zephyr/tests/bluetooth/shell
       build directory: /home/carles/src/zephyr/zephyr/build
       BOARD: qemu_x86 (origin: CMakeCache.txt)
-- west build: running target run
[0/1] To exit from QEMU enter: 'CTRL+a, x'[QEMU] CPU: qemu32,+nx,+pae
SeaBIOS (version rel-1.12.1-0-ga5cab58-dirty-20200202_184651-8999447e980d-zephyr
)
Booting from ROM..Optimal CONFIG_X86_MMU_PAGE_POOL_PAGES 7
*** Booting Zephyr OS build v2.2.0-rc1-135-g115641290460  ***
Type "help" for supported commands.Before any Bluetooth commands you must `bt init` to initialize the stack.


uart:~$ bt init
[00:00:01.580,000] <inf> fs_nvs: 8 Sectors of 1024 bytes
[00:00:01.590,000] <inf> fs_nvs: alloc wra: 0, 3f0
[00:00:01.590,000] <inf> fs_nvs: data wra: 0, 0
[00:00:01.670,000] <inf> bt_hci_core: No ID address. App must call settings_load()
Bluetooth initialized
[00:00:01.670,000] <inf> bt_hci_core: Identity: d9:a6:a2:da:16:5c (random)
[00:00:01.670,000] <inf> bt_hci_core: HCI: version 5.1 (0x0a) revision 0x0000, manufacturer 0x05f1
[00:00:01.680,000] <inf> bt_hci_core: LMP: version 5.1 (0x0a) subver 0xffff
[00:00:01.680,000] <inf> bt_settings: Saving ID
uart:~$

Seems to work fine, so closing the issue for now.