subsys/hawkBit: Debug log error in hawkbit example "CONFIG_LOG_STRDUP_MAX_STRING"

[jeronimoagullo]

Describe the bug
I am bulding the hawkbit example from zephyr\samples\subsys\mgmt\hawkbit-esp32.
A fatal error arises when the log level is set as DEBUG CONFIG_HAWKBIT_LOG_LEVEL_DBG=y. The error is caused due to the log_strdup functions. If I build with info log level CONFIG_HAWKBIT_LOG_LEVEL_INF, it works.

To Reproduce
Steps to reproduce the behavior:

1. my prj.conf file for esp32:

#Turn on the Hawkbit
CONFIG_HAWKBIT=y

#Main Stack Size
CONFIG_MAIN_STACK_SIZE=4096

#Minimal Heap mem pool size for the Hawkbit working
CONFIG_HEAP_MEM_POOL_SIZE=4096
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096

CONFIG_NET_IPV4=y
CONFIG_NET_IPV6=n

#Enable DHCPv4 server
CONFIG_NET_DHCPV4=y
CONFIG_NET_MGMT=y
CONFIG_NET_MGMT_EVENT=y

#Enable DNS Resolver
CONFIG_DNS_RESOLVER=y
CONFIG_DNS_SERVER_IP_ADDRESSES=y
CONFIG_DNS_SERVER1="8.8.8.8"
CONFIG_DNS_SERVER2="192.168.1.1"

#Optional if you would like test on the your server
CONFIG_SHELL=n
CONFIG_HAWKBIT_SHELL=n
CONFIG_KERNEL_SHELL=n
#CONFIG_SHELL_STACK_SIZE=4096

#Hawkbit polling mode
CONFIG_HAWKBIT_POLLING=y

#Config Hawkbit Server
CONFIG_HAWKBIT_SERVER="192.168.1.66"

#Debug helpers
CONFIG_LOG=y
CONFIG_LOG_DEFAULT_LEVEL=1
CONFIG_LOG_BACKEND_UART=y
CONFIG_HAWKBIT_LOG_LEVEL_DBG=y
CONFIG_NET_LOG=y
CONFIG_NET_SHELL=n

#General Config
CONFIG_NEWLIB_LIBC=y
CONFIG_LOG_BUFFER_SIZE=4096

#Generate HEX output
CONFIG_BUILD_OUTPUT_HEX=y

#LOG Maximum string define
CONFIG_LOG_STRDUP_MAX_STRING=100
CONFIG_LOG_STRDUP_BUF_COUNT=20

CONFIG_MCUBOOT_GENERATE_CONFIRMED_IMAGE=y

#### ESP32 ####
CONFIG_WIFI=y
CONFIG_WIFI_ESP32=y
CONFIG_ESP32_WIFI_STA_AUTO=y
CONFIG_HEAP_MEM_POOL_SIZE=98304

CONFIG_NETWORKING=y
CONFIG_NET_L2_ETHERNET=y

CONFIG_MBEDTLS=y
CONFIG_MBEDTLS_ENTROPY_ENABLED=y
CONFIG_MBEDTLS_KEY_EXCHANGE_ECDHE_ECDSA_ENABLED=y
CONFIG_MBEDTLS_ECP_ALL_ENABLED=y

CONFIG_ESP32_WIFI_SSID="myssid"
CONFIG_ESP32_WIFI_PASSWORD="mypassword"

# To reduce the IRAM use
CONFIG_ESP32_WIFI_IRAM_OPT=n
CONFIG_ESP32_WIFI_RX_IRAM_OPT=n

# Ensure an MCUboot-compatible binary is generated.
CONFIG_BOOTLOADER_MCUBOOT=y

2. Building

west build -b esp32 -p -- -DCONF_FILE="prj.conf"

3. During building, the following warning messages are displayed

warning: LOG_STRDUP_MAX_STRING (defined at subsys/logging\Kconfig.processing:126) was assigned the
value '100' but got the value ''. Check these unsatisfied dependencies: LOG1_DEFERRED (=n). See
http://docs.zephyrproject.org/latest/kconfig.html#CONFIG_LOG_STRDUP_MAX_STRING and/or look up
LOG_STRDUP_MAX_STRING in the menuconfig/guiconfig interface. The Application Development Primer,
Setting Configuration Values, and Kconfig - Tips and Best Practices sections of the manual might be
helpful too.

warning: LOG_STRDUP_BUF_COUNT (defined at subsys/logging\Kconfig.processing:135) was assigned the
value '20' but got the value ''. Check these unsatisfied dependencies: LOG1_DEFERRED (=n). See
http://docs.zephyrproject.org/latest/kconfig.html#CONFIG_LOG_STRDUP_BUF_COUNT and/or look up
LOG_STRDUP_BUF_COUNT in the menuconfig/guiconfig interface. The Application Development Primer,
Setting Configuration Values, and Kconfig - Tips and Best Practices sections of the manual might be
helpful too.

4. signing

west sign -t imgtool -B <path_signed_app> -- --key <key.pem> --confirm --version 1.0.0

5. flash the image

esptool.py -p <port> -b 115200 --before default_reset --after hard_reset --chip esp32  write_flash --flash_mode dio --flash_size 4MB --flash_freq 40m 0x1000 <path_signed_app>

6. See error

Leaving...
Hard resetting via RTS pin...
ot] chip revision: 1
[esp32] [INF] [boot_comm] chip revision: 1, min. bootloader chip revision: 0
[esp32] [INF] Enabling RNG early entropy source...
[esp32] [INF] *** Booting MCUboot build v1.9.0-37-g1d6f98e ***
[esp32] [INF] Primary image: magic=good, swap_type=0x1, copy_done=0x3, image_ok=0x1
[esp32] [INF] Scratch: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
[esp32] [INF] Boot source: primary slot
[esp32] [INF] Swap type: none
[esp32] [INF] Disabling RNG early entropy source...
[esp32] [INF] br_image_off = 0x10000
[esp32] [INF] ih_hdr_size = 0x20
[esp32] [INF] Loading image 0 - slot 0 from flash, area id: 1
[esp32] [INF] DRAM segment: start=0x15ff0, size=0x269c, vaddr=0x3ffb0000
[esp32] [INF] IRAM segment: start=0x1868c, size=0x1a6b0, vaddr=0x40080000
[esp32] [INF] start=0x40091c7c
?*** Booting Zephyr OS build v3.1.0-rc2-120-ge79c48f7c68a  ***


Backtrace:0x40092DEA:0x3FFEAB30 0x400D76D5:0x3FFEAB40 0x400D8E15:0x3FFEABC0 0x400E7416:0x3FFEAC20 0x400E7F4F:0x3FFEAC40 0x400E88CB:0x3FFEAE80 0x4008E935:0x3FFEAEC0 0x400D7B5B:0x3FFEAF00

[00:00:14.024,000] <inf> fs_nvs: 3 Sectors of 4096 bytes
[00:00:14.024,000] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:14.024,000] <inf> fs_nvs: data wra: 0, 0
[00:00:14.024,000] <dbg> hawkbit: hawkbit_init: Action id: current 1073423032
[00:00:14.024,000] <inf> hawkbit: Image is confirmed OK
[00:00:14.242,000] <inf> hawkbit: Polling target data from Hawkbit
[00:00:14.268,000] <dbg> hawkbit: hawkbit_dump_base: config.polling.sleep=00:05:00
[00:00:14.268,000] <err> os:  ** FATAL EXCEPTION
[00:00:14.268,000] <err> os:  ** CPU 0 EXCCAUSE 28 (load prohibited)
[00:00:14.268,000] <err> os:  **  PC 0x40092ded VADDR (nil)
[00:00:14.268,000] <err> os:  **  PS 0x60f20
[00:00:14.268,000] <err> os:  **    (INTLEVEL:0 EXCM: 0 UM:1 RING:0 WOE:1 OWB:15 CALLINC:2)
[00:00:14.268,000] <err> os:  **  A0 0x800d76d8  SP 0x3ffca899  A2 (nil)  A3 0xfffffffc
[00:00:14.268,000] <err> os:  **  A4 0xff  A5 0xff00  A6 0xff0000  A7 0xff000000
[00:00:14.268,000] <err> os:  **  A8 (nil)  A9 0x3ffeab60 A10 (nil) A11 0x3ffca760
[00:00:14.268,000] <err> os:  ** A12 0x60b20 A13 0x3ffca78a A14 0x30 A15 (nil)
[00:00:14.268,000] <err> os:  ** LBEG 0x40092ded LEND 0x40092dfd LCOUNT 0xffffffff
[00:00:14.268,000] <err> os:  ** SAR 0x4
[00:00:14.274,000] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:00:14.274,000] <err> os: Current thread: 0x3ffcd3e0 (unknown)
[00:00:14.410,000] <err> os: Halting system

7. decode the backtrace

xtensa-esp32-elf-addr2line -pfiaC -e build/zephyr/zephyr.elf 0x40092DEA:0x3FFEAB30 0x400D76D5:0x3FFEAB40 0x400D8E15:0x3FFEABC0 0x400E7416:0x3FFEAC20 0x400E7F4F:0x3FFEAC40 0x400E88CB:0x3FFEAE80 0x4008E935:0x3FFEAEC0 0x400D7B5B:0x3FFEAF00

output

0x40092dea: strlen at ??:?
0x400d76d5: append_string at C:/Workspace/zephyrproject/zephyr/lib/os/cbprintf_packaged.c:218
 (inlined by) append_string at C:/Workspace/zephyrproject/zephyr/lib/os/cbprintf_packaged.c:215
 (inlined by) cbprintf_package_convert at C:/Workspace/zephyrproject/zephyr/lib/os/cbprintf_packaged.c:798
0x400d8e15: cbprintf_package_copy at C:\Workspace\zephyrproject\zephyr\samples\subsys\mgmt\hawkbit-esp32\build/../../../../../include/zephyr/sys/cbprintf.h:445
 (inlined by) z_impl_z_log_msg2_static_create at C:/Workspace/zephyrproject/zephyr/subsys/logging/log_msg2.c:59
0x400e7416: z_log_msg2_static_create at C:\Workspace\zephyrproject\zephyr\samples\subsys\mgmt\hawkbit-esp32\build/zephyr/include/generated/syscalls/log_msg2.h:37
0x400e7f4f: hawkbit_dump_base at C:/Workspace/zephyrproject/zephyr/subsys/mgmt/hawkbit/hawkbit.c:576
 (inlined by) hawkbit_probe at C:/Workspace/zephyrproject/zephyr/subsys/mgmt/hawkbit/hawkbit.c:1094
0x400e88cb: autohandler at C:/Workspace/zephyrproject/zephyr/subsys/mgmt/hawkbit/hawkbit.c:1273
0x4008e935: work_queue_main at C:/Workspace/zephyrproject/zephyr/kernel/work.c:668
0x400d7b5b: z_thread_entry at C:/Workspace/zephyrproject/zephyr/lib/os/thread_entry.c:36

Additional context
The error arises in the function hawkbit_dump_base in zephyr/blob/main/subsys/mgmt/hawkbit/hawkbit.c. I guess that it occurs due to the log_strdup function.

static void hawkbit_dump_base(struct hawkbit_ctl_res *r)
{
	LOG_DBG("config.polling.sleep=%s", log_strdup(r->config.polling.sleep));
	LOG_DBG("_links.deploymentBase.href=%s",
		log_strdup(r->_links.deploymentBase.href));
	LOG_DBG("_links.configData.href=%s",
		log_strdup(r->_links.configData.href));
	LOG_DBG("_links.cancelAction.href=%s",
		log_strdup(r->_links.cancelAction.href));
}

I tried to add CONFIG_LOG1_DEFERRED=y into the config file, however it is not possible since this variable cannot be set manually. Furthermore, I saw in the guiconfig that the LOG1_DEFERRED is deprecated and I couldn't set.

How can I set the debug log level in hawkbit?

[sylvioalves]

@jeronimoagullo I have tested and confirm it is crashing. However, the root cause seems to be a NULL pointer at https://github.com/zephyrproject-rtos/zephyr/blob/main/subsys/mgmt/hawkbit/hawkbit.c#L575.
r->config.polling.sleep is null, which causes the crash. @ycsin, would you check whether this null pointer happens in there as well?
So I am still not sure whether this is ESP32 issue or Hawkit implementaion.

[ycsin]

How can I set the debug log level in hawkbit?

CONFIG_HAWKBIT_LOG_LEVEL_DBG / CONFIG_HAWKBIT_LOG_LEVEL_WRN for example.

The log_strdup was necessary for LOG1, which is the version that I was using (2.7 LTS), we had quite a bit of issues back then with the LOG2 and we were developing a product so we stayed on the LTS for the sake of stability. However I'm not sure what would happen if the arg passed into it happened to be a NULL ptr, maybe @nordic-krch have more insight in that regard.

@sylvioalves I don't really have anything to test now, didn't encounter this issue the last time I tested it.

From the log, it seems to be able to print the sleep string:

[00:00:14.268,000] <dbg> hawkbit: hawkbit_dump_base: config.polling.sleep=00:05:00

My understanding is that the HAWKBIT_PROBE request should either parse the links properly or it will error here, and when it does it will jump to cleanup, skipping the debug print.

@jeronimoagullo are you able to reproduce this error? If you could maybe you can breakpoint at here to check if there are indeed NULL pointers?

[jeronimoagullo]

hi @sylvioalves and @ycsin

Currently I don't have a jtag for debugging. I will receive a FT2232HL board with which I will be able to debug and add the brakpoint.

The only feedback that I can share currently is that the error arises in the function "hawkbit_dump_base" when the debug level of hawkbit module is debug.

Once I can check if the struct has a null pointer I will text again.

[ycsin]

The only feedback that I can share currently is that the error arises in the function "hawkbit_dump_base" when the debug level of hawkbit module is debug.

that's because the function is ran only when the level is set to debug

Let say the level is not debug, would the hawkbit be able to proceed and do the upgrade?

[jeronimoagullo]

hi @ycsin

yes, if the level is not debug (for example information), everything runs smothly. Thus, I think that it is just a matter of the debug messages.

Thank you very much

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

[ycsin]

@jeronimoagullo would it be possible for you to test #49232 and approve if it fixes the issue?