tests/posix/fs test show messages dropped in the logs

[arun1joshi]

Describe the bug
suddenly, running tests/posix/fs test cases shows messages dropped in logs.
I can see the issue for nrf52840_pca10056 board, but the same test passes for qemu_x86.

To Reproduce
Steps to reproduce the behavior:

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

Expected behavior
all test cases should be reported pass/fail

Impact
cannot judge if the test cases result is pass/fail?

**Screenshots or console output**
^[[1;31m--- 40 messages dropped ---
^[[0mPASS - test_fs_mkdir
===================================================================
starting test - test_fs_readdir
readdir test:
Listing dir /RAM:/testdir:
[FILE] TESTFILE.TX
PASS - test_fs_readdir
===================================================================
Test suite posix_fs_test succeeded
===================================================================
RunID: :bhdk
PROJECT EXECUTION SUCCESSFUL

Environment (please complete the following information):

• OS: Fedora29
• Toolchain: Zephyr SDK 0.10.0
• Commit SHA or Version used: [2d43d18]

Additional context
If I change to commit with the SDK v0.9.5, say [2320973], i don't see this issue and all test cases are reported pass.

[arun1joshi]

same issue with tests/kernel/common

�[1;31m--- 38 messages dropped ---
�[0m===================================================================

starting test - test_slist
PASS - test_slist
===================================================================
starting test - test_dlist
PASS - test_dlist
===================================================================
starting test - test_intmath
PASS - test_intmath
===================================================================
starting test - test_timeout_order
PASS - test_clock_uptime
�[1;31m--- 6 messages dropped ---
�[0m===================================================================
starting test - test_clock_cycle
PASS - test_clock_cycle
===================================================================
starting test - test_version
PASS - test_version
===================================================================
starting test - test_multilib
PASS - test_multilib
===================================================================
starting test - test_thread_context
PASS - test_thread_context
===================================================================
Test suite common failed.
===================================================================
RunID: ci-190325-1356-597:xjdn
PROJECT EXECUTION FAILED

[cinlyooi-intel]

Noticing the same problem on qemu_nios2 and altera_max10 for samples/subsys/logging/logger/

[00:00:04.129,999] <inf> main: Logging transient string:transient_string
Severity levels showcase.
[00:00:04.129,999] <err> main: Error message example.
[00:00:04.129,999] <wrn> main: Warning message example.
[00:00:04.129,999] <inf> main: Info message example.
[00:00:05.189,999] <inf> main: performance test - log message 254
--- 255 messages dropped ---
[00:00:05.189,999] <inf> main: performance test - log message 255

Unfortunately for me, my test harness in sample.yaml is looking for the string Logging performance showcase which is on the first few lines of the 255 messaged dropped. Thus, my test harness then declare the test case failed.

[pfalcon]

I don't see any connection described here between logging messages being dropped and tests fail.

Except for this one:

Unfortunately for me, my test harness in sample.yaml is looking for the string Logging performance showcase which is on the first few lines of the 255 messaged dropped. Thus, my test harness then declare the test case failed.

But then, your the harness is the culprit, and that's what needs to be fixed.

Unassigning from myself. If there's need for logging contact, it's @nordic-krch. I don't assign to him myself, as again, I don't see how logging is involved with any actual problems reported here.

[carlescufi]

@arun1joshi @cinlyooi-intel this is just a result of a buffer that is too small. You can increase the buffer size with:

CONFIG_LOG_BUFFER_SIZE=4096

in your prj.conf.

Since there are memory constraints in some of the boards I don't want to increase that size for all boards.

[carlescufi]

Expected behaviour, see previous comment.

[cinlyooi-intel]

@carlescufi

CONFIG_LOG_BUFFER_SIZE=4096

in your prj.conf.

Since there are memory constraints in some of the boards I don't want to increase that size for all boards.

I am reopening this because the issue did not happen before. It just happens now. Previously we were happily seeing all console messages, including very long ones.

[nashif]

Looks like a real bug to me. offending commit:

94ae61f765d385f2a55a92c53e3a940a79b41921 is the first bad commit
commit 94ae61f765d385f2a55a92c53e3a940a79b41921
Author: Krzysztof Chruscinski <[email protected]>
Date:   Wed Mar 13 09:54:56 2019 +0100

    logging: Force LOG_PRINTK option if RTT backend is used

    Log RTT backed is using mutex for locking access to RTT data.
    RTT console (which by default is used by printk) writes to
    RTT data directly and it cannot use mutex because it can be
    called from any context (including interrupt). If both
    modules access RTT buffer 0, data can be corrupted.

    This patch forces LOG_PRINTK option if RTT backend is used to
    ensure single point of access to RTT buffer 0 data.

    Signed-off-by: Krzysztof Chruscinski <[email protected]>

[nashif]

on this board, CONFIG_RTT_CONSOLE=y which leads to printk messages being dropped if we redirect them to logger...

[nordic-krch]

i'll take a look at that. As @nashif mentioned, it has to do with the fact that with RTT enabled printk obligatory goes through the logger. This commit (e980082) enabled RTT by default on nordic boards. There are then 2 options:

• increase buffer size
• reconsider enabling RTT by default

@jarz-nordic when you've done #12971, was your intention to enable RTT backend by default? What was the reasoning?

[jakub-uC]

@nordic-krch : Yes my intention was to enable RTT by default. Rationale behind is that these microcontrollers have a lot of memory so extra space for RTT won't hurt. In addition it enables a feature I need in shell tests for RTT backend. There was a github issue that file with this backend is not compiled and tested.

[carlescufi]

@nordic-krch how about another option, which is enabling CONFIG_LOG_IMMEDIATE in those tests? then we wouldn't need to increase the buffer size.

[nordic-krch]

@carlescufi , yes, that could be an option. Timing of printk going through logger with LOG_IMMEDIATE will be more or less the same as printk direct to uart.

[nashif]

raising to high, this is causing many tests to fail.

[pfalcon]

logging: Force LOG_PRINTK option if RTT backend is used

That's what appears to be the issue. As discussed before, printk is one thing, logging is another. Trying to mix them up leads ... well, to weird mix-ups.