diff --git a/CMakeLists.txt b/CMakeLists.txt index d4dd40cf66f39..512d7d1c63b7a 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -1984,22 +1984,39 @@ elseif(CONFIG_LOG_MIPI_SYST_USE_CATALOG) endif() if(LOG_DICT_DB_NAME_ARG) - if (NOT CONFIG_LOG_DICTIONARY_DB_TARGET) - set(LOG_DICT_DB_ALL_TARGET ALL) - endif() - add_custom_command( - OUTPUT ${LOG_DICT_DB_NAME} - COMMAND + set(log_dict_gen_command ${PYTHON_EXECUTABLE} ${ZEPHYR_BASE}/scripts/logging/dictionary/database_gen.py ${KERNEL_ELF_NAME} ${LOG_DICT_DB_NAME_ARG}=${LOG_DICT_DB_NAME} --build-header ${PROJECT_BINARY_DIR}/include/generated/zephyr/version.h - WORKING_DIRECTORY ${PROJECT_BINARY_DIR} - COMMENT "Generating logging dictionary database: ${LOG_DICT_DB_NAME}" - DEPENDS ${logical_target_for_zephyr_elf} ) - add_custom_target(log_dict_db_gen ${LOG_DICT_DB_ALL_TARGET} DEPENDS ${LOG_DICT_DB_NAME}) + + if (NOT CONFIG_LOG_DICTIONARY_DB_TARGET) + # If not using a separate target for generating logging dictionary + # database, add the generation to post build command to make sure + # the database is actually being generated. + list(APPEND + post_build_commands + COMMAND ${CMAKE_COMMAND} -E echo "Generating logging dictionary database: ${LOG_DICT_DB_NAME}" + COMMAND ${log_dict_gen_command} + ) + list(APPEND + post_build_byproducts + ${LOG_DICT_DB_NAME} + ) + else() + # Seprate build target for generating logging dictionary database. + # This needs to be explicitly called/used to generate the database. + add_custom_command( + OUTPUT ${LOG_DICT_DB_NAME} + COMMAND ${log_dict_gen_command} + WORKING_DIRECTORY ${PROJECT_BINARY_DIR} + COMMENT "Generating logging dictionary database: ${LOG_DICT_DB_NAME}" + DEPENDS ${logical_target_for_zephyr_elf} + ) + add_custom_target(log_dict_db_gen DEPENDS ${LOG_DICT_DB_NAME}) + endif() endif() # Add post_build_commands to post-process the final .elf file produced by diff --git a/include/zephyr/logging/log_output_dict.h b/include/zephyr/logging/log_output_dict.h index 23271cf34950d..12ab2aaad800e 100644 --- a/include/zephyr/logging/log_output_dict.h +++ b/include/zephyr/logging/log_output_dict.h @@ -30,10 +30,10 @@ enum log_dict_output_msg_type { */ struct log_dict_output_normal_msg_hdr_t { uint8_t type; - uint32_t domain:3; - uint32_t level:3; - uint32_t package_len:10; - uint32_t data_len:12; + uint32_t domain:4; + uint32_t level:4; + uint32_t package_len:16; + uint32_t data_len:16; uintptr_t source; log_timestamp_t timestamp; } __packed; diff --git a/scripts/logging/dictionary/dictionary_parser/__init__.py b/scripts/logging/dictionary/dictionary_parser/__init__.py index 16f2f9ec8e9c0..67f70c128cee7 100644 --- a/scripts/logging/dictionary/dictionary_parser/__init__.py +++ b/scripts/logging/dictionary/dictionary_parser/__init__.py @@ -9,6 +9,7 @@ """ from .log_parser_v1 import LogParserV1 +from .log_parser_v3 import LogParserV3 def get_parser(database): @@ -19,4 +20,8 @@ def get_parser(database): if db_ver in [1, 2]: return LogParserV1(database) + # DB version 3 correspond to v3 parser + if db_ver == 3: + return LogParserV3(database) + return None diff --git a/scripts/logging/dictionary/dictionary_parser/data_types.py b/scripts/logging/dictionary/dictionary_parser/data_types.py new file mode 100644 index 0000000000000..0ff4de7c34fce --- /dev/null +++ b/scripts/logging/dictionary/dictionary_parser/data_types.py @@ -0,0 +1,186 @@ +#!/usr/bin/env python3 +# +# Copyright (c) 2024 Intel Corporation +# +# SPDX-License-Identifier: Apache-2.0 + +""" +Contains a class to describe data types used for +dictionary logging. +""" + +import struct + +class DataTypes(): + """Class regarding data types, their alignments and sizes""" + INT = 0 + UINT = 1 + LONG = 2 + ULONG = 3 + LONG_LONG = 4 + ULONG_LONG = 5 + PTR = 6 + DOUBLE = 7 + LONG_DOUBLE = 8 + NUM_TYPES = 9 + + def __init__(self, database): + self.database = database + self.data_types = {} + + if database.is_tgt_64bit(): + self.add_data_type(self.LONG, "q") + self.add_data_type(self.LONG_LONG, "q") + self.add_data_type(self.PTR, "Q") + else: + self.add_data_type(self.LONG, "i") + self.add_data_type(self.LONG_LONG, "q") + self.add_data_type(self.PTR, "I") + + self.add_data_type(self.INT, "i") + self.add_data_type(self.DOUBLE, "d") + self.add_data_type(self.LONG_DOUBLE, "d") + + + @staticmethod + def get_stack_min_align(arch, is_tgt_64bit): + ''' + Correspond to the VA_STACK_ALIGN and VA_STACK_MIN_ALIGN + in cbprintf_internal.h. Note that there might be some + variations that is obtained via actually running through + the log parser. + + Return a tuple where the first element is stack alignment + value. The second element is true if alignment needs to + be further refined according to data type, false if not. + ''' + if arch == "arc": + if is_tgt_64bit: + need_further_align = True + stack_min_align = 8 + else: + need_further_align = False + stack_min_align = 1 + + elif arch == "arm64": + need_further_align = True + stack_min_align = 8 + + elif arch == "sparc": + need_further_align = False + stack_min_align = 1 + + elif arch == "x86": + if is_tgt_64bit: + need_further_align = True + stack_min_align = 8 + else: + need_further_align = False + stack_min_align = 1 + + elif arch == "riscv32e": + need_further_align = False + stack_min_align = 1 + + elif arch == "riscv": + need_further_align = True + + if is_tgt_64bit: + stack_min_align = 8 + else: + stack_min_align = 1 + + elif arch == "nios2": + need_further_align = False + stack_min_align = 1 + + else: + need_further_align = True + stack_min_align = 1 + + return (stack_min_align, need_further_align) + + + @staticmethod + def get_data_type_align(data_type, is_tgt_64bit): + ''' + Get the alignment for a particular data type. + ''' + if data_type == DataTypes.LONG_LONG: + align = 8 + elif data_type == DataTypes.LONG: + if is_tgt_64bit: + align = 8 + else: + align = 4 + else: + # va_list alignment is at least a integer + align = 4 + + return align + + + def add_data_type(self, data_type, fmt): + """Add one data type""" + if self.database.is_tgt_little_endian(): + endianness = "<" + else: + endianness = ">" + + formatter = endianness + fmt + + self.data_types[data_type] = {} + self.data_types[data_type]['fmt'] = formatter + + size = struct.calcsize(formatter) + + if data_type == self.LONG_DOUBLE: + # Python doesn't have long double but we still + # need to skip correct number of bytes + size = 16 + + self.data_types[data_type]['sizeof'] = size + + # Might need actual number for different architectures + # but these seem to work fine for now. + if self.database.is_tgt_64bit(): + align = 8 + else: + align = 4 + + # 'align' is used to "jump" over an argument so it has + # to be at least size of the data type. + align = max(align, size) + self.data_types[data_type]['align'] = align + + # 'stack_align' should correspond to VA_STACK_ALIGN + # in cbprintf_internal.h + stack_align, need_more_align = DataTypes.get_stack_min_align( + self.database.get_arch(), + self.database.is_tgt_64bit()) + + if need_more_align: + stack_align = DataTypes.get_data_type_align(data_type, + self.database.is_tgt_64bit()) + + self.data_types[data_type]['stack_align'] = stack_align + + + def get_sizeof(self, data_type): + """Get sizeof() of a data type""" + return self.data_types[data_type]['sizeof'] + + + def get_alignment(self, data_type): + """Get the alignment of a data type""" + return self.data_types[data_type]['align'] + + + def get_stack_alignment(self, data_type): + """Get the stack alignment of a data type""" + return self.data_types[data_type]['stack_align'] + + + def get_formatter(self, data_type): + """Get the formatter for a data type""" + return self.data_types[data_type]['fmt'] diff --git a/scripts/logging/dictionary/dictionary_parser/log_database.py b/scripts/logging/dictionary/dictionary_parser/log_database.py index 3e7b37e396f3a..83e34e4abebb9 100644 --- a/scripts/logging/dictionary/dictionary_parser/log_database.py +++ b/scripts/logging/dictionary/dictionary_parser/log_database.py @@ -49,6 +49,9 @@ "posix" : { "kconfig": "CONFIG_ARCH_POSIX", }, + "riscv32e" : { + "kconfig": "CONFIG_RISCV_ISA_RV32E", + }, "riscv" : { "kconfig": "CONFIG_RISCV", }, @@ -62,7 +65,7 @@ class LogDatabase(): """Class of log database""" # Update this if database format of dictionary based logging # has changed - ZEPHYR_DICT_LOG_VER = 2 + ZEPHYR_DICT_LOG_VER = 3 LITTLE_ENDIAN = True BIG_ENDIAN = False diff --git a/scripts/logging/dictionary/dictionary_parser/log_parser.py b/scripts/logging/dictionary/dictionary_parser/log_parser.py index 31ca7bb46b849..07b0419b7d0db 100644 --- a/scripts/logging/dictionary/dictionary_parser/log_parser.py +++ b/scripts/logging/dictionary/dictionary_parser/log_parser.py @@ -9,6 +9,44 @@ """ import abc +from colorama import Fore + +from .data_types import DataTypes + +LOG_LEVELS = [ + ('none', Fore.WHITE), + ('err', Fore.RED), + ('wrn', Fore.YELLOW), + ('inf', Fore.GREEN), + ('dbg', Fore.BLUE) +] + +def get_log_level_str_color(lvl): + """Convert numeric log level to string""" + if lvl < 0 or lvl >= len(LOG_LEVELS): + return ("unk", Fore.WHITE) + + return LOG_LEVELS[lvl] + + +def formalize_fmt_string(fmt_str): + """Replace unsupported formatter""" + new_str = fmt_str + + for spec in ['d', 'i', 'o', 'u', 'x', 'X']: + # Python doesn't support %ll for integer specifiers, so remove extra 'l' + new_str = new_str.replace("%ll" + spec, "%l" + spec) + + if spec in ['x', 'X']: + new_str = new_str.replace("%#ll" + spec, "%#l" + spec) + + # Python doesn't support %hh for integer specifiers, so remove extra 'h' + new_str = new_str.replace("%hh" + spec, "%h" + spec) + + # No %p for pointer either, so use %x + new_str = new_str.replace("%p", "0x%x") + + return new_str class LogParser(abc.ABC): @@ -16,6 +54,9 @@ class LogParser(abc.ABC): def __init__(self, database): self.database = database + self.data_types = DataTypes(self.database) + + @abc.abstractmethod def parse_log_data(self, logdata, debug=False): """Parse log data""" diff --git a/scripts/logging/dictionary/dictionary_parser/log_parser_v1.py b/scripts/logging/dictionary/dictionary_parser/log_parser_v1.py index e065837781fa6..124974e93109c 100644 --- a/scripts/logging/dictionary/dictionary_parser/log_parser_v1.py +++ b/scripts/logging/dictionary/dictionary_parser/log_parser_v1.py @@ -17,19 +17,12 @@ import colorama from colorama import Fore -from .log_parser import LogParser +from .log_parser import (LogParser, get_log_level_str_color, formalize_fmt_string) +from .data_types import DataTypes HEX_BYTES_IN_LINE = 16 -LOG_LEVELS = [ - ('none', Fore.WHITE), - ('err', Fore.RED), - ('wrn', Fore.YELLOW), - ('inf', Fore.GREEN), - ('dbg', Fore.BLUE) -] - # Need to keep sync with struct log_dict_output_msg_hdr in # include/logging/log_output_dict.h. # @@ -67,106 +60,6 @@ logger = logging.getLogger("parser") -def get_log_level_str_color(lvl): - """Convert numeric log level to string""" - if lvl < 0 or lvl >= len(LOG_LEVELS): - return ("unk", Fore.WHITE) - - return LOG_LEVELS[lvl] - - -def formalize_fmt_string(fmt_str): - """Replace unsupported formatter""" - new_str = fmt_str - - for spec in ['d', 'i', 'o', 'u', 'x', 'X']: - # Python doesn't support %ll for integer specifiers, so remove extra 'l' - new_str = new_str.replace("%ll" + spec, "%l" + spec) - - # Python doesn't support %hh for integer specifiers, so remove extra 'h' - new_str = new_str.replace("%hh" + spec, "%h" + spec) - - # No %p for pointer either, so use %x - new_str = new_str.replace("%p", "0x%x") - - return new_str - - -class DataTypes(): - """Class regarding data types, their alignments and sizes""" - INT = 0 - UINT = 1 - LONG = 2 - ULONG = 3 - LONG_LONG = 4 - ULONG_LONG = 5 - PTR = 6 - DOUBLE = 7 - LONG_DOUBLE = 8 - NUM_TYPES = 9 - - def __init__(self, database): - self.database = database - self.data_types = {} - - if database.is_tgt_64bit(): - self.add_data_type(self.LONG, "q") - self.add_data_type(self.LONG_LONG, "q") - self.add_data_type(self.PTR, "Q") - else: - self.add_data_type(self.LONG, "i") - self.add_data_type(self.LONG_LONG, "q") - self.add_data_type(self.PTR, "I") - - self.add_data_type(self.INT, "i") - self.add_data_type(self.DOUBLE, "d") - self.add_data_type(self.LONG_DOUBLE, "d") - - - def add_data_type(self, data_type, fmt): - """Add one data type""" - if self.database.is_tgt_little_endian(): - endianness = "<" - else: - endianness = ">" - - formatter = endianness + fmt - - self.data_types[data_type] = {} - self.data_types[data_type]['fmt'] = formatter - - size = struct.calcsize(formatter) - - if data_type == self.LONG_DOUBLE: - # Python doesn't have long double but we still - # need to skip correct number of bytes - size = 16 - - self.data_types[data_type]['sizeof'] = size - - # Might need actual number for different architectures - # but these seem to work fine for now. - if self.database.is_tgt_64bit(): - self.data_types[data_type]['align'] = 8 - else: - self.data_types[data_type]['align'] = 4 - - - def get_sizeof(self, data_type): - """Get sizeof() of a data type""" - return self.data_types[data_type]['sizeof'] - - - def get_alignment(self, data_type): - """Get the alignment of a data type""" - return self.data_types[data_type]['align'] - - - def get_formatter(self, data_type): - """Get the formatter for a data type""" - return self.data_types[data_type]['fmt'] - - class LogParserV1(LogParser): """Log Parser V1""" def __init__(self, database): @@ -190,8 +83,6 @@ def __init__(self, database): else: self.fmt_msg_timestamp = endian + FMT_MSG_TIMESTAMP_32 - self.data_types = DataTypes(self.database) - def __get_string(self, arg, arg_offset, string_tbl): one_str = self.database.find_string(arg) @@ -219,6 +110,7 @@ def process_one_fmt_str(self, fmt_str, arg_list, string_tbl): Python's string formatting""" idx = 0 arg_offset = 0 + arg_data_type = None is_parsing = False do_extract = False @@ -291,6 +183,11 @@ def process_one_fmt_str(self, fmt_str, arg_list, string_tbl): size = self.data_types.get_sizeof(arg_data_type) unpack_fmt = self.data_types.get_formatter(arg_data_type) + # Align the argument list by rounding up + stack_align = self.data_types.get_stack_alignment(arg_data_type) + if stack_align > 1: + arg_offset = int((arg_offset + (align - 1)) / align) * align + one_arg = struct.unpack_from(unpack_fmt, arg_list, arg_offset)[0] if fmt == 's': @@ -300,7 +197,8 @@ def process_one_fmt_str(self, fmt_str, arg_list, string_tbl): arg_offset += size # Align the offset - arg_offset = int((arg_offset + align - 1) / align) * align + if stack_align > 1: + arg_offset = int((arg_offset + align - 1) / align) * align return tuple(args) diff --git a/scripts/logging/dictionary/dictionary_parser/log_parser_v3.py b/scripts/logging/dictionary/dictionary_parser/log_parser_v3.py new file mode 100644 index 0000000000000..d6b3904e19662 --- /dev/null +++ b/scripts/logging/dictionary/dictionary_parser/log_parser_v3.py @@ -0,0 +1,383 @@ +#!/usr/bin/env python3 +# +# Copyright (c) 2021, 2024 Intel Corporation +# +# SPDX-License-Identifier: Apache-2.0 + +# Parsers are gonig to have very similar code. +# So tell pylint not to care. +# pylint: disable=duplicate-code + +""" +Dictionary-based Logging Parser Version 3 + +This contains the implementation of the parser for +version 3 databases. +""" + +import logging +import struct +import colorama +from colorama import Fore + +from .log_parser import (LogParser, get_log_level_str_color, formalize_fmt_string) +from .data_types import DataTypes + + +HEX_BYTES_IN_LINE = 16 + +# Need to keep sync with struct log_dict_output_msg_hdr in +# include/logging/log_output_dict.h. +# +# struct log_dict_output_normal_msg_hdr_t { +# uint8_t type; +# uint32_t domain:4; +# uint32_t level:4; +# uint32_t package_len:16; +# uint32_t data_len:16; +# uintptr_t source; +# log_timestamp_t timestamp; +# } __packed; +# +# Note "type" and "timestamp" are encoded separately below. +FMT_MSG_HDR_32 = "BHHI" +FMT_MSG_HDR_64 = "BHHQ" + +# Message type +# 0: normal message +# 1: number of dropped messages +FMT_MSG_TYPE = "B" + +# Depends on CONFIG_LOG_TIMESTAMP_64BIT +FMT_MSG_TIMESTAMP_32 = "I" +FMT_MSG_TIMESTAMP_64 = "Q" + +# Keep message types in sync with include/logging/log_output_dict.h +MSG_TYPE_NORMAL = 0 +MSG_TYPE_DROPPED = 1 + +# Number of dropped messages +FMT_DROPPED_CNT = "H" + + +logger = logging.getLogger("parser") + + +class LogParserV3(LogParser): + """Log Parser V1""" + def __init__(self, database): + super().__init__(database=database) + + if self.database.is_tgt_little_endian(): + endian = "<" + self.is_big_endian = False + else: + endian = ">" + self.is_big_endian = True + + self.fmt_msg_type = endian + FMT_MSG_TYPE + self.fmt_dropped_cnt = endian + FMT_DROPPED_CNT + + if self.database.is_tgt_64bit(): + self.fmt_msg_hdr = endian + FMT_MSG_HDR_64 + else: + self.fmt_msg_hdr = endian + FMT_MSG_HDR_32 + + if "CONFIG_LOG_TIMESTAMP_64BIT" in self.database.get_kconfigs(): + self.fmt_msg_timestamp = endian + FMT_MSG_TIMESTAMP_64 + else: + self.fmt_msg_timestamp = endian + FMT_MSG_TIMESTAMP_32 + + + def __get_string(self, arg, arg_offset, string_tbl): + one_str = self.database.find_string(arg) + if one_str is not None: + ret = one_str + else: + # The index from the string table is basically + # the order in va_list. Need to add to the index + # to skip the packaged string header and + # the format string. + str_idx = arg_offset + self.data_types.get_sizeof(DataTypes.PTR) * 2 + str_idx /= self.data_types.get_sizeof(DataTypes.INT) + + if int(str_idx) not in string_tbl: + ret = f'' + else: + ret = string_tbl[int(str_idx)] + + return ret + + + def process_one_fmt_str(self, fmt_str, arg_list, string_tbl): + """Parse the format string to extract arguments from + the binary arglist and return a tuple usable with + Python's string formatting""" + idx = 0 + arg_offset = 0 + arg_data_type = None + is_parsing = False + do_extract = False + + args = [] + + # Translated from cbvprintf_package() + for idx, fmt in enumerate(fmt_str): + if not is_parsing: + if fmt == '%': + is_parsing = True + arg_data_type = DataTypes.INT + continue + + elif fmt == '%': + # '%%' -> literal percentage sign + is_parsing = False + continue + + elif fmt == '*': + pass + + elif fmt.isdecimal() or str.lower(fmt) == 'l' \ + or fmt in (' ', '#', '-', '+', '.', 'h'): + # formatting modifiers, just ignore + continue + + elif fmt in ('j', 'z', 't'): + # intmax_t, size_t or ptrdiff_t + arg_data_type = DataTypes.LONG + + elif fmt in ('c', 'd', 'i', 'o', 'u') or str.lower(fmt) == 'x': + if fmt_str[idx - 1] == 'l': + if fmt_str[idx - 2] == 'l': + arg_data_type = DataTypes.LONG_LONG + else: + arg_data_type = DataTypes.LONG + else: + arg_data_type = DataTypes.INT + + is_parsing = False + do_extract = True + + elif fmt in ('s', 'p', 'n'): + arg_data_type = DataTypes.PTR + + is_parsing = False + do_extract = True + + elif str.lower(fmt) in ('a', 'e', 'f', 'g'): + # Python doesn't do"long double". + # + # Parse it as double (probably incorrect), but + # still have to skip enough bytes. + if fmt_str[idx - 1] == 'L': + arg_data_type = DataTypes.LONG_DOUBLE + else: + arg_data_type = DataTypes.DOUBLE + + is_parsing = False + do_extract = True + + else: + is_parsing = False + continue + + if do_extract: + do_extract = False + + align = self.data_types.get_alignment(arg_data_type) + size = self.data_types.get_sizeof(arg_data_type) + unpack_fmt = self.data_types.get_formatter(arg_data_type) + + # Align the argument list by rounding up + stack_align = self.data_types.get_stack_alignment(arg_data_type) + if stack_align > 1: + arg_offset = int((arg_offset + (align - 1)) / align) * align + + one_arg = struct.unpack_from(unpack_fmt, arg_list, arg_offset)[0] + + if fmt == 's': + one_arg = self.__get_string(one_arg, arg_offset, string_tbl) + + args.append(one_arg) + arg_offset += size + + # Align the offset + if stack_align > 1: + arg_offset = int((arg_offset + align - 1) / align) * align + + return tuple(args) + + + @staticmethod + def extract_string_table(str_tbl): + """Extract string table in a packaged log message""" + tbl = {} + + one_str = "" + next_new_string = True + # Translated from cbvprintf_package() + for one_ch in str_tbl: + if next_new_string: + str_idx = one_ch + next_new_string = False + continue + + if one_ch == 0: + tbl[str_idx] = one_str + one_str = "" + next_new_string = True + continue + + one_str += chr(one_ch) + + return tbl + + + @staticmethod + def print_hexdump(hex_data, prefix_len, color): + """Print hex dump""" + hex_vals = "" + chr_vals = "" + chr_done = 0 + + for one_hex in hex_data: + hex_vals += f'{one_hex:02x} ' + chr_vals += chr(one_hex) + chr_done += 1 + + if chr_done == HEX_BYTES_IN_LINE / 2: + hex_vals += " " + chr_vals += " " + + elif chr_done == HEX_BYTES_IN_LINE: + print(f"{color}%s%s|%s{Fore.RESET}" % ((" " * prefix_len), + hex_vals, chr_vals)) + hex_vals = "" + chr_vals = "" + chr_done = 0 + + if len(chr_vals) > 0: + hex_padding = " " * (HEX_BYTES_IN_LINE - chr_done) + print(f"{color}%s%s%s|%s{Fore.RESET}" % ((" " * prefix_len), + hex_vals, hex_padding, chr_vals)) + + + def parse_one_normal_msg(self, logdata, offset): + """Parse one normal log message and print the encoded message""" + # Parse log message header + domain_lvl, pkg_len, data_len, source_id = struct.unpack_from(self.fmt_msg_hdr, + logdata, offset) + offset += struct.calcsize(self.fmt_msg_hdr) + + timestamp = struct.unpack_from(self.fmt_msg_timestamp, logdata, offset)[0] + offset += struct.calcsize(self.fmt_msg_timestamp) + + # domain_id, level + if self.is_big_endian: + level = domain_lvl & 0x0F + domain_id = (domain_lvl >> 4) & 0x0F + else: + domain_id = domain_lvl & 0x0F + level = (domain_lvl >> 4) & 0x0F + + level_str, color = get_log_level_str_color(level) + source_id_str = self.database.get_log_source_string(domain_id, source_id) + + # Skip over data to point to next message (save as return value) + next_msg_offset = offset + pkg_len + data_len + + # Offset from beginning of cbprintf_packaged data to end of va_list arguments + offset_end_of_args = struct.unpack_from("B", logdata, offset)[0] + offset_end_of_args *= self.data_types.get_sizeof(DataTypes.INT) + offset_end_of_args += offset + + # Extra data after packaged log + extra_data = logdata[(offset + pkg_len):next_msg_offset] + + # Number of appended strings in package + num_packed_strings = struct.unpack_from("B", logdata, offset+1)[0] + + # Number of read-only string indexes + num_ro_str_indexes = struct.unpack_from("B", logdata, offset+2)[0] + offset_end_of_args += num_ro_str_indexes + + # Number of read-write string indexes + num_rw_str_indexes = struct.unpack_from("B", logdata, offset+3)[0] + offset_end_of_args += num_rw_str_indexes + + # Extract the string table in the packaged log message + string_tbl = self.extract_string_table(logdata[offset_end_of_args:(offset + pkg_len)]) + + if len(string_tbl) != num_packed_strings: + logger.error("------ Error extracting string table") + return None + + # Skip packaged string header + offset += self.data_types.get_sizeof(DataTypes.PTR) + + # Grab the format string + # + # Note the negative offset to __get_string(). It is because + # the offset begins at 0 for va_list. However, the format string + # itself is before the va_list, so need to go back the width of + # a pointer. + fmt_str_ptr = struct.unpack_from(self.data_types.get_formatter(DataTypes.PTR), + logdata, offset)[0] + fmt_str = self.__get_string(fmt_str_ptr, + -self.data_types.get_sizeof(DataTypes.PTR), + string_tbl) + offset += self.data_types.get_sizeof(DataTypes.PTR) + + if not fmt_str: + logger.error("------ Error getting format string at 0x%x", fmt_str_ptr) + return None + + args = self.process_one_fmt_str(fmt_str, logdata[offset:offset_end_of_args], string_tbl) + + fmt_str = formalize_fmt_string(fmt_str) + log_msg = fmt_str % args + + if level == 0: + print(f"{log_msg}", end='') + log_prefix = "" + else: + log_prefix = f"[{timestamp:>10}] <{level_str}> {source_id_str}: " + print(f"{color}%s%s{Fore.RESET}" % (log_prefix, log_msg)) + + if data_len > 0: + # Has hexdump data + self.print_hexdump(extra_data, len(log_prefix), color) + + # Point to next message + return next_msg_offset + + + def parse_log_data(self, logdata, debug=False): + """Parse binary log data and print the encoded log messages""" + offset = 0 + + while offset < len(logdata): + # Get message type + msg_type = struct.unpack_from(self.fmt_msg_type, logdata, offset)[0] + offset += struct.calcsize(self.fmt_msg_type) + + if msg_type == MSG_TYPE_DROPPED: + num_dropped = struct.unpack_from(self.fmt_dropped_cnt, logdata, offset) + offset += struct.calcsize(self.fmt_dropped_cnt) + + print(f"--- {num_dropped} messages dropped ---") + + elif msg_type == MSG_TYPE_NORMAL: + ret = self.parse_one_normal_msg(logdata, offset) + if ret is None: + return False + + offset = ret + + else: + logger.error("------ Unknown message type: %s", msg_type) + return False + + return True + +colorama.init() diff --git a/scripts/logging/dictionary/log_parser.py b/scripts/logging/dictionary/log_parser.py index eef60c03840fe..c2b20b0fda952 100755 --- a/scripts/logging/dictionary/log_parser.py +++ b/scripts/logging/dictionary/log_parser.py @@ -132,6 +132,8 @@ def main(): else: logger.debug("# Endianness: Big") + logger.debug("# Database version: %d", database.get_version()) + ret = log_parser.parse_log_data(logdata, debug=args.debug) if not ret: logger.error("ERROR: there were error(s) parsing log data") diff --git a/subsys/logging/Kconfig.frontends b/subsys/logging/Kconfig.frontends index 7a725421fb9e3..17e42d341ba2c 100644 --- a/subsys/logging/Kconfig.frontends +++ b/subsys/logging/Kconfig.frontends @@ -9,7 +9,7 @@ config LOG_FRONTEND_DICT_UART select MPSC_PBUF depends on UART_ASYNC_API || UART_INTERRUPT_DRIVEN imply LOG_FMT_SECTION - imply LOG_FMT_SECTION_STRIP + imply LOG_FMT_SECTION_STRIP if !LOG_ALWAYS_RUNTIME help Frontend sends data in binary dictionary mode. diff --git a/subsys/logging/Kconfig.misc b/subsys/logging/Kconfig.misc index 4f10680f4b6f9..08515db64fb89 100644 --- a/subsys/logging/Kconfig.misc +++ b/subsys/logging/Kconfig.misc @@ -69,6 +69,7 @@ config LOG_FMT_SECTION_STRIP depends on LOG_DICTIONARY_SUPPORT depends on LOG_FMT_SECTION depends on LINKER_DEVNULL_SUPPORT + depends on !LOG_ALWAYS_RUNTIME imply LINKER_DEVNULL_MEMORY imply LOG_FMT_STRING_VALIDATE diff --git a/subsys/logging/Kconfig.template.log_format_config b/subsys/logging/Kconfig.template.log_format_config index 0b2dbe0d403a9..14e112e4879ef 100644 --- a/subsys/logging/Kconfig.template.log_format_config +++ b/subsys/logging/Kconfig.template.log_format_config @@ -20,7 +20,7 @@ config LOG_BACKEND_$(backend)_OUTPUT_DICTIONARY bool "Dictionary" select LOG_DICTIONARY_SUPPORT imply LOG_FMT_SECTION - imply LOG_FMT_SECTION_STRIP + imply LOG_FMT_SECTION_STRIP if !LOG_ALWAYS_RUNTIME help Backend is in dictionary-based logging output mode. diff --git a/tests/subsys/logging/dictionary/CMakeLists.txt b/tests/subsys/logging/dictionary/CMakeLists.txt new file mode 100644 index 0000000000000..163d0c3ee51ec --- /dev/null +++ b/tests/subsys/logging/dictionary/CMakeLists.txt @@ -0,0 +1,8 @@ +# SPDX-License-Identifier: Apache-2.0 + +cmake_minimum_required(VERSION 3.20.0) + +find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE}) +project(logging_dictionary) + +target_sources(app PRIVATE src/main.c) diff --git a/tests/subsys/logging/dictionary/prj.conf b/tests/subsys/logging/dictionary/prj.conf new file mode 100644 index 0000000000000..2465b6cdd08a7 --- /dev/null +++ b/tests/subsys/logging/dictionary/prj.conf @@ -0,0 +1,9 @@ +CONFIG_LOG=y +CONFIG_LOG_PRINTK=y +CONFIG_LOG_BACKEND_UART_OUTPUT_DICTIONARY_HEX=y +CONFIG_LOG_BACKEND_UART_OUTPUT_DICTIONARY=y +CONFIG_LOG_BACKEND_UART=y + +# Immediate mode needed for twister/pytest +# to capture output without delays. +CONFIG_LOG_MODE_IMMEDIATE=y diff --git a/tests/subsys/logging/dictionary/pytest/conftest.py b/tests/subsys/logging/dictionary/pytest/conftest.py new file mode 100644 index 0000000000000..29d3de55d10bf --- /dev/null +++ b/tests/subsys/logging/dictionary/pytest/conftest.py @@ -0,0 +1,14 @@ +# +# Copyright (c) 2024 Intel Corporation. +# +# SPDX-License-Identifier: Apache-2.0 +# + +import pytest + +def pytest_addoption(parser): + parser.addoption('--fpu', action="store_true") + +@pytest.fixture() +def is_fpu_build(request): + return request.config.getoption('--fpu') diff --git a/tests/subsys/logging/dictionary/pytest/test_logging_dictionary.py b/tests/subsys/logging/dictionary/pytest/test_logging_dictionary.py new file mode 100644 index 0000000000000..68548ce47677d --- /dev/null +++ b/tests/subsys/logging/dictionary/pytest/test_logging_dictionary.py @@ -0,0 +1,159 @@ +# +# Copyright (c) 2024 Intel Corporation. +# +# SPDX-License-Identifier: Apache-2.0 +# + +''' +Pytest harness to test the output of the dictionary logging. +''' + +import logging +import os +import shlex +import subprocess +import re + +from twister_harness import DeviceAdapter + +ZEPHYR_BASE = os.getenv("ZEPHYR_BASE") + +logger = logging.getLogger(__name__) + +def process_logs(dut: DeviceAdapter, build_dir): + ''' + This grabs the encoded log from console and parse the log + through the dictionary logging parser. + + Returns the decoded log lines. + ''' + # Make sure the log parser script is there... + parser_script = os.path.join(ZEPHYR_BASE, "scripts", "logging", "dictionary", "log_parser.py") + assert os.path.isfile(parser_script) + logger.info(f'Log parser script: {parser_script}') + + # 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) + logger.info(f'Dictionary JSON: {dictionary_json}') + + # Read the encoded logs and save them to a file + # as the log parser requires file as input + handler_output = dut.readlines_until(regex = '^##ZLOGV1##[0-9]+', timeout = 10.0) + + encoded_logs = handler_output[-1] + + encoded_log_file = os.path.join(build_dir, "encoded.log") + with open(encoded_log_file, 'w', encoding='utf-8') as fp: + fp.write(encoded_logs) + + # Run the log parser + cmd = [parser_script, '--hex', dictionary_json, encoded_log_file] + logger.info(f'Running parser script: {shlex.join(cmd)}') + result = subprocess.run(cmd, capture_output=True, text=True, check=True) + assert result.returncode == 0 + + # Grab the decoded log lines from stdout, print a copy and return it + decoded_logs = result.stdout + logger.info(f'Decoded logs: {decoded_logs}') + + return decoded_logs + + +def expected_regex_common(): + ''' + Return an array of compiled regular expression for matching + the decoded log lines. + ''' + return [ + # *** Booting Zephyr OS build *** + re.compile(r'^[*][*][*] Booting Zephyr OS build [0-9a-z.-]+'), + # Hello World! + re.compile(r'[\s]+Hello World! [\w-]+'), + # [ 10] hello_world: error string + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: error string'), + # [ 10] hello_world: main: debug string + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: debug string'), + # [ 10] hello_world: info string + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: info string'), + # [ 10] hello_world: main: int8_t 1, uint8_t 2 + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: int8_t 1, uint8_t 2'), + # [ 10] hello_world: main: int16_t 16, uint16_t 17 + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: int16_t 16, uint16_t 17'), + # [ 10] hello_world: main: int32_t 32, uint32_t 33 + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: int32_t 32, uint32_t 33'), + # [ 10] hello_world: main: int64_t 64, uint64_t 65 + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: int64_t 64, uint64_t 65'), + # [ 10] hello_world: main: char ! + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: char !'), + # [ 10] hello_world: main: s str static str c str + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: s str static str c str'), + # [ 10] hello_world: main: d str dynamic str + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: d str dynamic str'), + # [ 10] hello_world: main: mixed str dynamic str --- dynamic str \ + # --- another dynamic str --- another dynamic str + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: mixed str dynamic str ' + '--- dynamic str --- another dynamic str --- another dynamic str'), + # [ 10] hello_world: main: mixed c/s ! static str dynamic str static str ! + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: mixed c/s ! static str ' + 'dynamic str static str !'), + # [ 10] hello_world: main: pointer 0x1085f9 + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: pointer 0x[0-9a-f]+'), + # [ 10] hello_world: main: For HeXdUmP! + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: For HeXdUmP!'), + # 48 45 58 44 55 4d 50 21 20 48 45 58 44 55 4d 50 |HEXDUMP! HEXDUMP + re.compile(r'[\s]+[ ]+[0-9a-f ]{48,52}[|]HEXDUMP! HEXDUMP'), + # 40 20 48 45 58 44 55 4d 50 23 |@ HEXDUM P# + re.compile(r'[\s]+[ ]+[0-9a-f ]{48,52}[|]@ HEXDUM P#'), + ] + + +def expected_regex_fpu(): + ''' + Return an array of additional compiled regular expression for matching + the decoded log lines for FPU builds. + ''' + return [ + # [ 10] hello_world: main: float 66.669998, double 68.690000 + re.compile(r'[\s]+[\[][0-9,:\. ]+[\]] hello_world: main: ' + r'float 66[\.][0-9-\.]+, double 68[\.][0-9-\.]+'), + ] + + +def regex_matching(decoded_logs, expected_regex): + ''' + Given the decoded log lines and an array of compiled regular expression, + match all of them and display whether a line is found or not. + + Return True if all regular expressions have corresponding matches, + False otherwise. + ''' + regex_results = [ex_re.search(decoded_logs) for ex_re in expected_regex] + + # Using 1:1 mapping between regex_results and expected_regex, so + # cannot use enumeration. + # + # pylint: disable=consider-using-enumerate + for idx in range(len(regex_results)): + if regex_results[idx]: + logger.info(f'Found: {regex_results[idx].group(0).strip()}') + else: + logger.info(f'NOT FOUND: {expected_regex[idx]}') + + return all(regex_results) + + +def test_logging_dictionary(dut: DeviceAdapter, is_fpu_build): + ''' + Main entrance to setup test result validation. + ''' + build_dir = dut.device_config.build_dir + + logger.info(f'FPU build? {is_fpu_build}') + + decoded_logs = process_logs(dut, build_dir) + + assert regex_matching(decoded_logs, expected_regex_common()) + + if is_fpu_build: + assert regex_matching(decoded_logs, expected_regex_fpu()) diff --git a/tests/subsys/logging/dictionary/src/main.c b/tests/subsys/logging/dictionary/src/main.c new file mode 100644 index 0000000000000..1e4b5f3fecf0e --- /dev/null +++ b/tests/subsys/logging/dictionary/src/main.c @@ -0,0 +1,100 @@ +/* + * Copyright (c) 2012-2014 Wind River Systems, Inc. + * Copyright (c) 2021 Intel Corporation + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include +#include +#include +#include + +LOG_MODULE_REGISTER(hello_world, LOG_LEVEL_DBG); + +static const char *hexdump_msg = "HEXDUMP! HEXDUMP@ HEXDUMP#"; + +int main(void) +{ + int8_t i8 = 1; + uint8_t u8 = 2; + int16_t i16 = 16; + uint16_t u16 = 17; + int32_t i32 = 32; + uint32_t u32 = 33; + int64_t i64 = 64; + uint64_t u64 = 65; + char c = '!'; + char *s = "static str"; + char *s1 = "c str"; + char vs0[32]; + char vs1[32]; + void *p = s; + + printk("Hello World! %s\n", CONFIG_BOARD); + + LOG_ERR("error string"); + LOG_DBG("debug string"); + LOG_INF("info string"); + + LOG_DBG("int8_t %" PRId8 ", uint8_t %" PRIu8, i8, u8); + LOG_DBG("int16_t %" PRId16 ", uint16_t %" PRIu16, i16, u16); + LOG_DBG("int32_t %" PRId32 ", uint32_t %" PRIu32, i32, u32); + LOG_DBG("int64_t %" PRId64 ", uint64_t %" PRIu64, i64, u64); + + memset(vs0, 0, sizeof(vs0)); + snprintk(&vs0[0], sizeof(vs0), "%s", "dynamic str"); + + memset(vs1, 0, sizeof(vs1)); + snprintk(&vs1[0], sizeof(vs1), "%s", "another dynamic str"); + + LOG_DBG("char %c", c); + LOG_DBG("s str %s %s", s, s1); + LOG_DBG("d str %s", vs0); + LOG_DBG("mixed str %s %s %s %s %s %s %s", vs0, "---", vs0, "---", vs1, "---", vs1); + LOG_DBG("mixed c/s %c %s %s %s %c", c, s, vs0, s, c); + + LOG_DBG("pointer %p", p); + + LOG_HEXDUMP_DBG(hexdump_msg, strlen(hexdump_msg), "For HeXdUmP!"); + +#ifdef CONFIG_FPU + float f = 66.67; + double d = 68.69; + + LOG_DBG("float %f, double %f", (double)f, d); +#ifdef CONFIG_CBPRINTF_PACKAGE_LONGDOUBLE + long double ld = 70.71L; + + LOG_DBG("long double %Lf", ld); +#endif +#endif + +#if defined(CONFIG_STDOUT_CONSOLE) + /* + * When running through twister with pytest, we need to add a newline + * at the end of logging output for the output to be registered via + * pipe or FIFO in the pytest harness as reading is on a line-by-line + * basis. So send newline characters to flush the output. + */ + fputc('\r', stdout); + fputc('\n', stdout); +#endif + + return 0; +} + +static int rt_demo_cmd(const struct shell *sh, size_t argc, char **argv) +{ + ARG_UNUSED(sh); + LOG_ERR("demo %s", argc > 1 ? argv[1] : ""); + LOG_WRN("demo %s", argc > 1 ? argv[1] : ""); + LOG_INF("demo %s", argc > 1 ? argv[1] : ""); + LOG_DBG("demo %s", argc > 1 ? argv[1] : ""); + + return 0; +} + +SHELL_CMD_REGISTER(log_rt_demo, NULL, "Command can be used to test runtime filtering", rt_demo_cmd); diff --git a/tests/subsys/logging/dictionary/testcase.yaml b/tests/subsys/logging/dictionary/testcase.yaml new file mode 100644 index 0000000000000..91f00946d7745 --- /dev/null +++ b/tests/subsys/logging/dictionary/testcase.yaml @@ -0,0 +1,34 @@ +common: + # For twister runs, the following arch/platforms use logging backends + # which do not output dictionary logging in hexidecimal format, + # and thus cannot be used for testing. Currently, only UART + # logging backend does that. + arch_exclude: + - posix + platform_exclude: + - qemu_xtensa + - qemu_xtensa/dc233c/mmu +tests: + logging.dictionary: + tags: logging + integration_platforms: + - qemu_x86 + - qemu_x86_64 + harness: pytest + harness_config: + pytest_root: + - "pytest/test_logging_dictionary.py" + logging.dictionary.fpu: + tags: logging + filter: CONFIG_CPU_HAS_FPU + extra_configs: + - CONFIG_FPU=y + harness: pytest + harness_config: + pytest_root: + - "pytest/test_logging_dictionary.py" + pytest_args: + - "--fpu" + integration_platforms: + - qemu_x86 + - qemu_x86_64