Skip to content

Commit e5ea973

Browse files
dcpleungdcpleung
committed
tests: logging/dictionary: enable pytest to test output
Add pytest to test the output of dictionary logging to make sure the encoded logs can be decoded back into strings, and to also make sure the decoded logs have the expected strings. Signed-off-by: Daniel Leung <[email protected]>
1 parent d6a08e5 commit e5ea973

File tree

5 files changed

+209
-2
lines changed

5 files changed

+209
-2
lines changed

‎tests/subsys/logging/dictionary/prj.conf‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,3 +3,7 @@ CONFIG_LOG_PRINTK=y
33
CONFIG_LOG_BACKEND_UART_OUTPUT_DICTIONARY_HEX=y
44
CONFIG_LOG_BACKEND_UART_OUTPUT_DICTIONARY=y
55
CONFIG_LOG_BACKEND_UART=y
6+
7+
# Immediate mode needed for twister/pytest
8+
# to capture output without delays.
9+
CONFIG_LOG_MODE_IMMEDIATE=y

‎tests/subsys/logging/dictionary/pytest/conftest.py‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,14 @@
1+
#
2+
# Copyright (c) 2024 Intel Corporation.
3+
#
4+
# SPDX-License-Identifier: Apache-2.0
5+
#
6+
7+
import pytest
8+
9+
def pytest_addoption(parser):
10+
parser.addoption('--fpu', action="store_true")
11+
12+
@pytest.fixture()
13+
def is_fpu_build(request):
14+
return request.config.getoption('--fpu')

‎tests/subsys/logging/dictionary/pytest/test_logging_dictionary.py‎

Lines changed: 159 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,159 @@
1+
#
2+
# Copyright (c) 2024 Intel Corporation.
3+
#
4+
# SPDX-License-Identifier: Apache-2.0
5+
#
6+
7+
'''
8+
Pytest harness to test the output of the dictionary logging.
9+
'''
10+
11+
import logging
12+
import os
13+
import shlex
14+
import subprocess
15+
import re
16+
17+
from twister_harness import DeviceAdapter
18+
19+
ZEPHYR_BASE = os.getenv("ZEPHYR_BASE")
20+
21+
logger = logging.getLogger(__name__)
22+
23+
def process_logs(dut: DeviceAdapter, build_dir):
24+
'''
25+
This grabs the encoded log from console and parse the log
26+
through the dictionary logging parser.
27+
28+
Returns the decoded log lines.
29+
'''
30+
# Make sure the log parser script is there...
31+
parser_script = os.path.join(ZEPHYR_BASE, "scripts", "logging", "dictionary", "log_parser.py")
32+
assert os.path.isfile(parser_script)
33+
logger.info(f'Log parser script: {parser_script}')
34+
35+
# And also the dictionary JSON file is there...
36+
dictionary_json = os.path.join(build_dir, "zephyr", "log_dictionary.json")
37+
assert os.path.isfile(dictionary_json)
38+
logger.info(f'Dictionary JSON: {dictionary_json}')
39+
40+
# Read the encoded logs and save them to a file
41+
# as the log parser requires file as input
42+
handler_output = dut.readlines_until(regex = '^##ZLOGV1##[0-9]+', timeout = 10.0)
43+
44+
encoded_logs = handler_output[-1]
45+
46+
encoded_log_file = os.path.join(build_dir, "encoded.log")
47+
with open(encoded_log_file, 'w', encoding='utf-8') as fp:
48+
fp.write(encoded_logs)
49+
50+
# Run the log parser
51+
cmd = [parser_script, '--hex', dictionary_json, encoded_log_file]
52+
logger.info(f'Running parser script: {shlex.join(cmd)}')
53+
result = subprocess.run(cmd, capture_output=True, text=True, check=True)
54+
assert result.returncode == 0
55+
56+
# Grab the decoded log lines from stdout, print a copy and return it
57+
decoded_logs = result.stdout
58+
logger.info(f'Decoded logs: {decoded_logs}')
59+
60+
return decoded_logs
61+
62+
63+
def expected_regex_common():
64+
'''
65+
Return an array of compiled regular expression for matching
66+
the decoded log lines.
67+
'''
68+
return [
69+
# *** Booting Zephyr OS build <version> ***
70+
re.compile(r'^[*][*][*] Booting Zephyr OS build [0-9a-z.-]+'),
71+
# Hello World! <board name>
72+
re.compile(r'[\s]+Hello World! [\w-]+'),
73+
# [ 10] <err> hello_world: error string
74+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <err> hello_world: error string'),
75+
# [ 10] <dbg> hello_world: main: debug string
76+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: debug string'),
77+
# [ 10] <inf> hello_world: info string
78+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <inf> hello_world: info string'),
79+
# [ 10] <dbg> hello_world: main: int8_t 1, uint8_t 2
80+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: int8_t 1, uint8_t 2'),
81+
# [ 10] <dbg> hello_world: main: int16_t 16, uint16_t 17
82+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: int16_t 16, uint16_t 17'),
83+
# [ 10] <dbg> hello_world: main: int32_t 32, uint32_t 33
84+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: int32_t 32, uint32_t 33'),
85+
# [ 10] <dbg> hello_world: main: int64_t 64, uint64_t 65
86+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: int64_t 64, uint64_t 65'),
87+
# [ 10] <dbg> hello_world: main: char !
88+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: char !'),
89+
# [ 10] <dbg> hello_world: main: s str static str c str
90+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: s str static str c str'),
91+
# [ 10] <dbg> hello_world: main: d str dynamic str
92+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: d str dynamic str'),
93+
# [ 10] <dbg> hello_world: main: mixed str dynamic str --- dynamic str \
94+
# --- another dynamic str --- another dynamic str
95+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: mixed str dynamic str '
96+
'--- dynamic str --- another dynamic str --- another dynamic str'),
97+
# [ 10] <dbg> hello_world: main: mixed c/s ! static str dynamic str static str !
98+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: mixed c/s ! static str '
99+
'dynamic str static str !'),
100+
# [ 10] <dbg> hello_world: main: pointer 0x1085f9
101+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: pointer 0x[0-9a-f]+'),
102+
# [ 10] <dbg> hello_world: main: For HeXdUmP!
103+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: For HeXdUmP!'),
104+
# 48 45 58 44 55 4d 50 21 20 48 45 58 44 55 4d 50 |HEXDUMP! HEXDUMP
105+
re.compile(r'[\s]+[ ]+[0-9a-f ]{48,52}[|]HEXDUMP! HEXDUMP'),
106+
# 40 20 48 45 58 44 55 4d 50 23 |@ HEXDUM P#
107+
re.compile(r'[\s]+[ ]+[0-9a-f ]{48,52}[|]@ HEXDUM P#'),
108+
]
109+
110+
111+
def expected_regex_fpu():
112+
'''
113+
Return an array of additional compiled regular expression for matching
114+
the decoded log lines for FPU builds.
115+
'''
116+
return [
117+
# [ 10] <dbg> hello_world: main: float 66.669998, double 68.690000
118+
re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] <dbg> hello_world: main: '
119+
r'float 66[\.][0-9-\.]+, double 68[\.][0-9-\.]+'),
120+
]
121+
122+
123+
def regex_matching(decoded_logs, expected_regex):
124+
'''
125+
Given the decoded log lines and an array of compiled regular expression,
126+
match all of them and display whether a line is found or not.
127+
128+
Return True if all regular expressions have corresponding matches,
129+
False otherwise.
130+
'''
131+
regex_results = [ex_re.search(decoded_logs) for ex_re in expected_regex]
132+
133+
# Using 1:1 mapping between regex_results and expected_regex, so
134+
# cannot use enumeration.
135+
#
136+
# pylint: disable=consider-using-enumerate
137+
for idx in range(len(regex_results)):
138+
if regex_results[idx]:
139+
logger.info(f'Found: {regex_results[idx].group(0).strip()}')
140+
else:
141+
logger.info(f'NOT FOUND: {expected_regex[idx]}')
142+
143+
return all(regex_results)
144+
145+
146+
def test_logging_dictionary(dut: DeviceAdapter, is_fpu_build):
147+
'''
148+
Main entrance to setup test result validation.
149+
'''
150+
build_dir = dut.device_config.build_dir
151+
152+
logger.info(f'FPU build? {is_fpu_build}')
153+
154+
decoded_logs = process_logs(dut, build_dir)
155+
156+
assert regex_matching(decoded_logs, expected_regex_common())
157+
158+
if is_fpu_build:
159+
assert regex_matching(decoded_logs, expected_regex_fpu())

‎tests/subsys/logging/dictionary/src/main.c‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -71,6 +71,18 @@ int main(void)
7171
LOG_DBG("long double %Lf", ld);
7272
#endif
7373
#endif
74+
75+
#if defined(CONFIG_STDOUT_CONSOLE)
76+
/*
77+
* When running through twister with pytest, we need to add a newline
78+
* at the end of logging output for the output to be registered via
79+
* pipe or FIFO in the pytest harness as reading is on a line-by-line
80+
* basis. So send newline characters to flush the output.
81+
*/
82+
fputc('\r', stdout);
83+
fputc('\n', stdout);
84+
#endif
85+
7486
return 0;
7587
}
7688

‎tests/subsys/logging/dictionary/testcase.yaml‎

Lines changed: 20 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,34 @@
1+
common:
2+
# For twister runs, the following arch/platforms use logging backends
3+
# which do not output dictionary logging in hexidecimal format,
4+
# and thus cannot be used for testing. Currently, only UART
5+
# logging backend does that.
6+
arch_exclude:
7+
- posix
8+
platform_exclude:
9+
- qemu_xtensa
10+
- qemu_xtensa/dc233c/mmu
111
tests:
212
logging.dictionary:
3-
build_only: true
413
tags: logging
514
integration_platforms:
615
- qemu_x86
716
- qemu_x86_64
17+
harness: pytest
18+
harness_config:
19+
pytest_root:
20+
- "pytest/test_logging_dictionary.py"
821
logging.dictionary.fpu:
9-
build_only: true
1022
tags: logging
1123
filter: CONFIG_CPU_HAS_FPU
1224
extra_configs:
1325
- CONFIG_FPU=y
26+
harness: pytest
27+
harness_config:
28+
pytest_root:
29+
- "pytest/test_logging_dictionary.py"
30+
pytest_args:
31+
- "--fpu"
1432
integration_platforms:
1533
- qemu_x86
1634
- qemu_x86_64

0 commit comments

Comments
 (0)