Assert crash in logger's out_func

[pdunaj]

Describe the bug

ASSERTION FAIL [out_ctx->control_block->offset <= out_ctx->size] @ /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:91

To Reproduce
Steps to reproduce the behavior:

1. Emit a lot of messages and wait for crash. In my case it happens quickly.

Expected behavior
Logger should not crash.

Impact
Debugging is impossible.

Screenshots or console output
Put above.

Environment (please complete the following information):
rev 9fe81e9

Additional context

[pdunaj]

Hi @nordic-krch , have you seen this issue?

[nordic-krch]

@pdunaj do you have option LOG_INPLACE_PROCESS enabled?

[pdunaj]

part of backtrace

#116 prefix_print (func_on=true, flags=10, log_output=0x2c7d4 <log_output>, msg=0x20007e50 <log_msg_pool_buf+3872>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:476
#117 log_output_msg_process (log_output=log_output@entry=0x2c7d4 <log_output>, msg=msg@entry=0x20007e50 <log_msg_pool_buf+3872>, flags=flags@entry=10)
    at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:511
#118 0x0000872c in put (backend=<optimized out>, msg=0x20007e50 <log_msg_pool_buf+3872>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_backend_rtt.c:197
#119 0x000074c0 in log_backend_put (msg=0x20007e50 <log_msg_pool_buf+3872>, backend=<optimized out>) at /home/padu/work/fw-nrfconnect-zephyr/include/logging/log_backend.h:94
#120 msg_process (bypass=false, msg=0x20007e50 <log_msg_pool_buf+3872>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:362
#121 log_process (bypass=bypass@entry=false) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:399
#122 0x000075c6 in log_process (bypass=false) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:389
#123 msg_finalize (src_level=..., msg=0x20007ef0 <log_msg_pool_buf+4032>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:67
#124 log_printk (fmt=fmt@entry=0x1 <z_finalize_fd> "\235", ap=..., ap@entry=...) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:176
#125 0x00002942 in printk (fmt=0x2aea0 "ASSERTION FAIL [%s] @ %s:%d\n") at /home/padu/work/fw-nrfconnect-zephyr/misc/printk.c:341
#126 0x0000833a in out_func (c=<optimized out>, ctx=<optimized out>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:91
#127 0x0000cb5a in _prf (func=func@entry=0x8311 <out_func>, dest=0x2c7d4 <log_output>, format=0x2c6b5 "%08lu] ", format@entry=0x2aba8 <log_const_ble_scan> "<\270\002", vargs=...,
    vargs@entry=...) at /home/padu/work/fw-nrfconnect-zephyr/lib/libc/minimal/source/stdout/prf.c:464
#128 0x00007f66 in print_formatted (log_output=<optimized out>, fmt=0x2c6b4 "[%08lu] ") at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:108
#129 0x00008660 in timestamp_print (flags=10, log_output=0x2c7d4 <log_output>, msg=0x20007e70 <log_msg_pool_buf+3904>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:145
#130 prefix_print (func_on=true, flags=10, log_output=0x2c7d4 <log_output>, msg=0x20007e70 <log_msg_pool_buf+3904>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:476
#131 log_output_msg_process (log_output=log_output@entry=0x2c7d4 <log_output>, msg=msg@entry=0x20007e70 <log_msg_pool_buf+3904>, flags=flags@entry=10)
    at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_output.c:511
#132 0x0000872c in put (backend=<optimized out>, msg=0x20007e70 <log_msg_pool_buf+3904>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_backend_rtt.c:197
#133 0x000074c0 in log_backend_put (msg=0x20007e70 <log_msg_pool_buf+3904>, backend=<optimized out>) at /home/padu/work/fw-nrfconnect-zephyr/include/logging/log_backend.h:94
#134 msg_process (bypass=false, msg=0x20007e70 <log_msg_pool_buf+3904>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:362
#135 log_process (bypass=<optimized out>) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:399
#136 0x00007648 in log_process (bypass=false) at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:333
#137 log_panic () at /home/padu/work/fw-nrfconnect-zephyr/subsys/logging/log_core.c:333
#138 0x0000c160 in _Fault (esf=0x20006c00 <log_strdup_pool_buf+4560>, exc_return=<optimized out>) at /home/padu/work/fw-nrfconnect-zephyr/arch/arm/core/fault.c:674
#139 0x0000c402 in __usage_fault () at /home/padu/work/fw-nrfconnect-zephyr/arch/arm/core/fault_s.S:143
#140 <signal handler called>
#141 0xc51973ba in ?? ()

Logger does not handle panic mode correctly?

[pdunaj]

Hi @nordic-krch , no. We disable this.

[pdunaj]

@nordic-krch , the problem happened after we migrated to logger in our event manager. It composes quite log strings. It seems that it is enough to do following multiple times to get logger go to fault that leads to above bt.

LOG_INF("e: %s %s", et->name, log_strdup("dupaasduhasidaiusdhiauhsdiahsiudhasdasdasd"));

[b0661]

Did you check the the stack size of the logger thread? I had similar scenarios with too low stack size.

[pdunaj]

Hi @b0661 , thanks for the suggestion. Indeed it helped :)

[pdunaj]

I am closing the issue as increasing the thread stack resolved the problem.

[nordic-krch]

good to know but i suspect that there is still an issue in handling panic mode if panic triggers another panic. Since ideally you should get MPU fault message (if stack protection is enabled) and not that assert. And you haven't seen that, right?

[pdunaj]

@nordic-krch no.