subsys: logging: dictionary: logging.dictionary{.fpu} fail #75253

katgiadla · 2024-07-01T12:04:57Z

Describe the bug
Tests:

tests/subsys/logging/dictionary/logging.dictionary
tests/subsys/logging/dictionary/logging.dictionary.fpu
fail.

Observed for:

nrf5340dk/nrf5340/cpuapp/ns
nrf54l15pdk/nrf54l15/cpuapp
nrf54h20dk/nrf54h20/cpurad
nrf54h20dk/nrf54h20/cpuapp
nrf9160dk/nrf9160 (only tests/subsys/logging/dictionary/logging.dictionary)
nrf9160dk/nrf9160/ns (only tests/subsys/logging/dictionary/logging.dictionary)

To Reproduce
Steps to reproduce the behavior:

have nrf5340dk/nrf5340/cpuapp connected
go to your zephyr dir
call ./scripts/twister -T tests/subsys/logging/dictionary/ -p nrf5340dk/nrf5340/cpuapp/ns --device-testing --device-serial /dev/ttyACM1 -v --inline-logs --west-flash="--erase"
See console output with error

Expected behavior
Valid console output

Impact
Not clear

Logs and console output
Logs for nrf9160dk/nrf9160 and nrf9160dk/nrf9160/ns:

11:23:49.989:DEBUG:twister_harness.device.factory: Get device type "hardware"
11:23:49.990:DEBUG:twister_harness.device.hardware_adapter: Opening serial connection for /dev/serial/by-id/usb-SEGGER_J-Link_000960019472-if00
11:23:49.991:DEBUG:twister_harness.device.hardware_adapter: Flashing device 960019472
11:23:49.991:DEBUG:twister_harness.device.hardware_adapter: Flashing command: /usr/local/bin/west flash --skip-rebuild --build-dir /jenkins_cache/test-zephyr-sanitycheck/zephyr/zephyr/twister-out/nrf9160dk_nrf9160/tests/subsys/logging/dictionary/logging.dictionary --runner nrfjprog -- --erase --dev-id 960019472
11:23:55.244:DEBUG:twister_harness.device.hardware_adapter: Flashing finished
11:23:55.246:INFO:test_logging_dictionary: FPU build? False
11:23:55.246:INFO:test_logging_dictionary: Log parser script: /zephyr/zephyr/zephyr/scripts/logging/dictionary/log_parser.py
11:23:55.246:INFO:test_logging_dictionary: Dictionary JSON: /zephyr/zephyr/twister-out/nrf9160dk_nrf9160/tests/subsys/logging/dictionary/logging.dictionary/zephyr/log_dictionary.json
11:23:55.651:DEBUG:twister_harness.device.device_adapter: #: ##ZLOGV1##0000080000000000000030430000020000000b6e000000000c00000000000000ad43000003000000f66b0000ec6b0000001008000000020000004144000002000000a85d000000400c00000002000000bf44000003000000975d00005e6c00000030080000000200000053450000020000008b5d000000401400000002000000d1450000050000006d5d00005e6c000001000000020000000040140000000200000093460000050000004f5d00005e6c00001000000011000000004014000000020000005547000005000000335d00005e6c00002000000021000000004020000000020000001848000008000000135d00005e6c0000a10c000040000000000000004100000000000000004010000000020000001e49000004000000075d00005e6c00002100000000401400000002000000c949000005000000f75c00005e6c00001b6c0000156c000000401d000000020000008b4a000004010000ea5c00005e6c0000000000000364796e616d6963207374720000406c00000002000000824b00000a040000c75c00005e6c000000000000266c000000000000266c000000000000266c0000000000000364796e616d696320737472000564796e616d6963207374720007616e6f746865722064796e616d6963207374720009616e6f746865722064796e616d6963207374720000402d00000002000000394e000008010000aa5c00005e6c0000210000001b6c0000000000001b6c0000210000000564796e616d6963207374720000401000000002000000894f0000040000009b5c00005e6c00001b6c0000004010001a00020000003550000004000000945c00005e6c0000456c000048455844554d50212048455844554d50402048455844554d5023
11:24:05.266:ERROR:twister_harness.device.device_adapter: Read from device timeout occurred
11:24:05.383:DEBUG:twister_harness.device.hardware_adapter: Closed serial connection for /dev/serial/by-id/usb-SEGGER_J-Link_000960019472-if00

Logs for nrf54l15pdk/nrf54l15/cpuapp, nrf54h20dk/nrf54h20/cpuapp and nrf54h20dk/nrf54h20/cpurad:

INFO    -
 _____________________________logging.dictionary.test_logging_dictionary_____________________________
AssertionError: assert False
 +  where False = <function isfile at 0x7fa8f14b8a60>('/zephyr/zephyr/twister-out/nrf54l15pdk_nrf54l15_cpuapp/tests/subsys/logging/dictionary/logging.dictionary/zephyr/log_dictionary.json')
 +    where <function isfile at 0x7fa8f14b8a60> = <module 'posixpath' from '/usr/local/lib/python3.9/posixpath.py'>.isfile
 +      where <module 'posixpath' from '/usr/local/lib/python3.9/posixpath.py'> = os.path
 ____________________________________________________________________________________________________
...
 logger.info(f'FPU build? {is_fpu_build}')
 >       decoded_logs = process_logs(dut, build_dir)
zephyr/tests/subsys/logging/dictionary/pytest/test_logging_dictionary.py:154:
...
 # And also the dictionary JSON file is there...
 dictionary_json = os.path.join(build_dir, "zephyr", "log_dictionary.json")
 >       assert os.path.isfile(dictionary_json)
 E       AssertionError: assert False
 E        +  where False = <function isfile at 0x7fa8f14b8a60>('/zephyr/zephyr/twister-out/nrf54l15pdk_nrf54l15_cpuapp/tests/subsys/logging/dictionary/logging.dictionary/zephyr/log_dictionary.json')
 E        +    where <function isfile at 0x7fa8f14b8a60> = <module 'posixpath' from '/usr/local/lib/python3.9/posixpath.py'>.isfile
 E        +      where <module 'posixpath' from '/usr/local/lib/python3.9/posixpath.py'> = os.path
zephyr/tests/subsys/logging/dictionary/pytest/test_logging_dictionary.py:37: AssertionError

Logs for nrf5340dk/nrf5340/cpuapp/ns:

11:23:54.257:DEBUG:twister_harness.device.factory: Get device type "hardware"
11:23:54.258:DEBUG:twister_harness.device.hardware_adapter: Opening serial connection for /dev/serial/by-id/usb-SEGGER_J-Link_000960168656-if04
11:23:54.259:DEBUG:twister_harness.device.hardware_adapter: Flashing device 960168656
11:23:54.259:DEBUG:twister_harness.device.hardware_adapter: Flashing command: /usr/local/bin/west flash --skip-rebuild --build-dir /zephyr/zephyr/twister-out/nrf5340dk_nrf5340_cpuapp_ns/tests/subsys/logging/dictionary/logging.dictionary --runner nrfjprog -- --erase --dev-id 960168656
11:24:01.603:DEBUG:twister_harness.device.hardware_adapter: Flashing finished
11:24:01.604:INFO:test_logging_dictionary: FPU build? False
11:24:01.604:INFO:test_logging_dictionary: Log parser script: /zephyr/zephyr/zephyr/scripts/logging/dictionary/log_parser.py
11:24:01.605:INFO:test_logging_dictionary: Dictionary JSON: /zephyr/zephyr/twister-out/nrf5340dk_nrf5340_cpuapp_ns/tests/subsys/logging/dictionary/logging.dictionary/zephyr/log_dictionary.json
11:24:11.631:ERROR:twister_harness.device.device_adapter: Read from device timeout occurred
11:24:11.706:DEBUG:twister_harness.device.hardware_adapter: Closed serial connection for /dev/serial/by-id/usb-SEGGER_J-Link_000960168656-if04

Environment (please complete the following information):

OS: Ubuntu 20.04.1 LTS
Toolchain: Zephyr SDK 0.16.5-1
Commit SHA or Version used: v3.7.0-rc2-4-g2c34da96f0e3

Additional context
Probably introduced by PR #72829.

The text was updated successfully, but these errors were encountered:

katgiadla · 2024-07-01T12:29:20Z

@dcpleung, could you look at this?

nashif · 2024-07-01T12:30:33Z

This is not nordic specific.

pkunieck · 2024-07-01T13:37:09Z

Also reproduced for:

intel_adsp/ace15_mtpm
intel_adsp/ace20_lnl
intel_adsp/cavs25
mec172xevb_assy6906
mec15xxevb_assy6853
it8xxx2_evb
npcx9m6f_evb
frdm_k64f
up_squared
intel_ish_5_4_1/intel_ish_5_4_1/simics
intel_ish_5_8_0/intel_ish_5_8_0/simics

dcpleung · 2024-07-01T17:15:35Z

For nrf54l15pdk/nrf54l15/cpuapp, nrf54h20dk/nrf54h20/cpuapp and nrf54h20dk/nrf54h20/cpurad (the second log block above), the log_dictionary.json is NOT under <build_dir>/zephyr/ but under <build_dir>/dictionary/zephyr/, which is not what is expected. And this extra directory is only added when running under twister. That's the reason for file not being found.

The first log block above for nrf9160dk/nrf9160 and nrf9160dk/nrf9160/ns had the log output but twister timed out.

The third log block above for nrf5340dk/nrf5340/cpuapp/ns had no output from device at all.

I will need to find some hardware to reproduce.

When doing device testing, there may be some other characters being printed before the dictionary logging header string. So change the regex to ignore those characters. Fixes zephyrproject-rtos#75253 Signed-off-by: Daniel Leung <[email protected]>

dcpleung · 2024-07-01T21:58:38Z

#75297 works on frdm_k64f.

I also attempted to account for sysbuild where the JSON file is located elsewhere. However, I do not have any of those devices to actually run twister against. Can anyone test that?

When doing device testing, there may be some other characters being printed before the dictionary logging header string. Also the delay boot banner may also be there. So change the regex to ignore those them. Fixes zephyrproject-rtos#75253 Signed-off-by: Daniel Leung <[email protected]>

gchwier · 2024-07-02T08:03:46Z

look into https://github.com/zephyrproject-rtos/zephyr/blob/main/scripts/pylib/pytest-twister-harness/src/twister_harness/twister_harness_config.py#L42

you can use as dut.device_config.app_build_dir in test_logging_dictionary to have both sysbuild and non-sysbuild scenarios covered

When doing device testing, there may be some other characters being printed before the dictionary logging header string. Also the delay boot banner may also be there. So change the regex to ignore those them. Fixes zephyrproject-rtos#75253 Signed-off-by: Daniel Leung <[email protected]>

dcpleung · 2024-07-03T00:08:39Z

I have updated the PR, which works on both frdm_k64f and up_squared.

pkunieck · 2024-07-05T10:27:13Z

We still have reproduction on 4 machines:

mec172xevb_assy6906
intel_adsp/cavs25
intel_adsp/ace20_lnl
intel_adsp/ace15_mtpm

dcpleung · 2024-07-08T20:19:56Z

The audio DSP platforms should not be running the dictionary logging tests as they are not using the UART logging backend... actually they don't have UART at all.

dcpleung · 2024-07-08T21:52:44Z

#75623 should be able to deal with mec17x failures.

katgiadla added bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug platform: nRF Nordic nRFx labels Jul 1, 2024

zephyrbot assigned anangl and masz-nordic Jul 1, 2024

katgiadla added the area: Logging label Jul 1, 2024

nashif unassigned anangl and masz-nordic Jul 1, 2024

nashif removed the platform: nRF Nordic nRFx label Jul 1, 2024

nashif assigned dcpleung Jul 1, 2024

nashif added priority: high High impact/importance bug and removed priority: low Low impact/importance bug labels Jul 1, 2024

katgiadla changed the title ~~subsys: logging: dictionary: logging.dictionary{.fpu} fail at Nordic platforms~~ subsys: logging: dictionary: logging.dictionary{.fpu} fail Jul 1, 2024

dcpleung mentioned this issue Jul 1, 2024

tests: logging/dictionary: fix pytest failures on hardware #75297

Merged

nashif closed this as completed in #75297 Jul 4, 2024

pkunieck reopened this Jul 5, 2024

dcpleung linked a pull request Jul 8, 2024 that will close this issue

tests: logging/dictionary: filter for backend #75620

Merged

dcpleung mentioned this issue Jul 8, 2024

tests: logging/dictionary: pytest only looks at last output #75623

Merged

nashif closed this as completed in #75620 Jul 9, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

subsys: logging: dictionary: logging.dictionary{.fpu} fail #75253

subsys: logging: dictionary: logging.dictionary{.fpu} fail #75253

katgiadla commented Jul 1, 2024 •

edited

Loading

katgiadla commented Jul 1, 2024 •

edited

Loading

nashif commented Jul 1, 2024

pkunieck commented Jul 1, 2024 •

edited

Loading

dcpleung commented Jul 1, 2024 •

edited

Loading

dcpleung commented Jul 1, 2024 •

edited

Loading

gchwier commented Jul 2, 2024

dcpleung commented Jul 3, 2024

pkunieck commented Jul 5, 2024

dcpleung commented Jul 8, 2024

dcpleung commented Jul 8, 2024

subsys: logging: dictionary: logging.dictionary{.fpu} fail #75253

subsys: logging: dictionary: logging.dictionary{.fpu} fail #75253

Comments

katgiadla commented Jul 1, 2024 • edited Loading

katgiadla commented Jul 1, 2024 • edited Loading

nashif commented Jul 1, 2024

pkunieck commented Jul 1, 2024 • edited Loading

dcpleung commented Jul 1, 2024 • edited Loading

dcpleung commented Jul 1, 2024 • edited Loading

gchwier commented Jul 2, 2024

dcpleung commented Jul 3, 2024

pkunieck commented Jul 5, 2024

dcpleung commented Jul 8, 2024

dcpleung commented Jul 8, 2024

katgiadla commented Jul 1, 2024 •

edited

Loading

katgiadla commented Jul 1, 2024 •

edited

Loading

pkunieck commented Jul 1, 2024 •

edited

Loading

dcpleung commented Jul 1, 2024 •

edited

Loading

dcpleung commented Jul 1, 2024 •

edited

Loading