scripts/logging: Handle partly read packets

The current implementation of the serial log parser is running in a loop -
every 2 seconds it checks if there is any information ready to be read, and
in this case, it reads this information and parses it.
In case the last packet of the information is not fully available, the
script will read only the first part of the packet, and will fail when
parsing, ending the run with an error.

This should not the be the case, as it is not an error to have only part
of the packet in the buffer.
This commit fixes this problem - now, instead of failing because the parser
does not have enough information, the parser will parse all the full
packets it have, and keep the last, partial packet in the queue, to be
parsed together with the next chunk of data.

This is done by updating the log parsers to return the amount of parsed
data when trying to parse the information, and updating the calling scripts
to correctly handle this new return value.
Additionally, the parser is now quietly failing in case of having a partial
message, and throw an exception for any other kind of error in the parsing
(instead of returning a boolean return code).

In addition to the partial packet handling, the current commit also do the
following, minor improvements:
* parserlib now fails by throwing an exception, instead of exiting - this
  is done to make it possible to choose a different handling for the errors
  from the calling code, if needed.
* The dictionary and parser are now created before the parse operation.
  This makes the uart parser more efficient, and also removes the
  previously duplicated messages of build id, target architecture and
  endianess (which was printed every time new information was received from
  the UART).

Signed-off-by: Omri Sarig <[email protected]>

Author: Omri Sarig

scripts/logging/dictionary/dictionary_parser/log_parser_v1.py

@@ -255,6 +255,18 @@ def print_hexdump(hex_data, prefix_len, color):
             print(f"{color}%s%s%s|%s{Fore.RESET}" % ((" " * prefix_len),
                   hex_vals, hex_padding, chr_vals))
 
+    def get_full_msg_hdr_size(self):
+        """Get the size of the full message header"""
+        return struct.calcsize(self.fmt_msg_type) + \
+            struct.calcsize(self.fmt_msg_hdr) + \
+            struct.calcsize(self.fmt_msg_timestamp)
+
+    def get_normal_msg_size(self, logdata, offset):
+        """Get the needed size of the normal log message at offset"""
+        log_desc, _ = struct.unpack_from(self.fmt_msg_hdr, logdata, offset)
+        pkg_len = (log_desc >> 6) & int(math.pow(2, 10) - 1)
+        data_len = (log_desc >> 16) & int(math.pow(2, 12) - 1)
+        return self.get_full_msg_hdr_size() + pkg_len + data_len
 
     def parse_one_normal_msg(self, logdata, offset):
         """Parse one normal log message and print the encoded message"""
@@ -341,33 +353,53 @@ def parse_one_normal_msg(self, logdata, offset):
         # Point to next message
         return next_msg_offset
 
+    def parse_one_msg(self, logdata, offset):
+        if offset + struct.calcsize(self.fmt_msg_type) > len(logdata):
+            return False, offset
 
-    def parse_log_data(self, logdata, debug=False):
-        """Parse binary log data and print the encoded log messages"""
-        offset = 0
+        # Get message type
+        msg_type = struct.unpack_from(self.fmt_msg_type, logdata, offset)[0]
 
-        while offset < len(logdata):
-            # Get message type
-            msg_type = struct.unpack_from(self.fmt_msg_type, logdata, offset)[0]
+        if msg_type == MSG_TYPE_DROPPED:
+
+            if offset + struct.calcsize(self.fmt_dropped_cnt) > len(logdata):
+                return False, offset
             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)
+            num_dropped = struct.unpack_from(self.fmt_dropped_cnt, logdata, offset)
+            offset += struct.calcsize(self.fmt_dropped_cnt)
 
-                print(f"--- {num_dropped} messages dropped ---")
+            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
+        elif msg_type == MSG_TYPE_NORMAL:
 
-                offset = ret
+            if ((offset + self.get_full_msg_hdr_size() > len(logdata)) or
+                (offset + self.get_normal_msg_size(logdata, offset) > len(logdata))):
+                return False, offset
 
-            else:
-                logger.error("------ Unknown message type: %s", msg_type)
-                return False
+            offset += struct.calcsize(self.fmt_msg_type)
+
+            ret = self.parse_one_normal_msg(logdata, offset)
+            if ret is None:
+                raise ValueError("Error parsing normal log message")
+
+            offset = ret
+
+        else:
+            logger.error("------ Unknown message type: %s", msg_type)
+            raise ValueError(f"Unknown message type: {msg_type}")
+
+        return True, offset
+
+    def parse_log_data(self, logdata, debug=False):
+        """Parse binary log data and print the encoded log messages"""
+        offset = 0
+        still_parsing = True
+
+        while offset < len(logdata) and still_parsing:
+            still_parsing, offset = self.parse_one_msg(logdata, offset)
+
+        return offset
 
-        return True
 
 colorama.init()

scripts/logging/dictionary/dictionary_parser/log_parser_v3.py

@@ -260,6 +260,20 @@ def print_hexdump(hex_data, prefix_len, color):
             print(f"{color}%s%s%s|%s{Fore.RESET}" % ((" " * prefix_len),
                   hex_vals, hex_padding, chr_vals))
 
+    def get_full_msg_hdr_size(self):
+        """Get the size of the full message header"""
+        return struct.calcsize(self.fmt_msg_type) + \
+            struct.calcsize(self.fmt_msg_hdr) + \
+            struct.calcsize(self.fmt_msg_timestamp)
+
+    def get_normal_msg_size(self, logdata, offset):
+        """Get the needed size of the normal log message at offset"""
+        _, pkg_len, data_len, _ = struct.unpack_from(
+            self.fmt_msg_hdr,
+            logdata,
+            offset + struct.calcsize(self.fmt_msg_type),
+        )
+        return self.get_full_msg_hdr_size() + pkg_len + data_len
 
     def parse_one_normal_msg(self, logdata, offset):
         """Parse one normal log message and print the encoded message"""
@@ -350,33 +364,54 @@ def parse_one_normal_msg(self, logdata, offset):
         # Point to next message
         return next_msg_offset
 
+    def parse_one_msg(self, logdata, offset):
+        if offset + struct.calcsize(self.fmt_msg_type) > len(logdata):
+            return False, offset
 
-    def parse_log_data(self, logdata, debug=False):
-        """Parse binary log data and print the encoded log messages"""
-        offset = 0
+        # Get message type
+        msg_type = struct.unpack_from(self.fmt_msg_type, logdata, offset)[0]
+
+        if msg_type == MSG_TYPE_DROPPED:
+
+            if offset + struct.calcsize(self.fmt_dropped_cnt) > len(logdata):
+                return False, offset
 
-        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)
+            num_dropped = struct.unpack_from(self.fmt_dropped_cnt, logdata, offset)
+            offset += struct.calcsize(self.fmt_dropped_cnt)
 
-                print(f"--- {num_dropped} messages dropped ---")
+            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
+        elif msg_type == MSG_TYPE_NORMAL:
 
-                offset = ret
+            if ((offset + self.get_full_msg_hdr_size() > len(logdata)) or
+                (offset + self.get_normal_msg_size(logdata, offset) > len(logdata))):
+                return False, offset
 
-            else:
-                logger.error("------ Unknown message type: %s", msg_type)
-                return False
+            offset += struct.calcsize(self.fmt_msg_type)
+
+            ret = self.parse_one_normal_msg(logdata, offset)
+            if ret is None:
+                raise ValueError("Error parsing normal log message")
+
+            offset = ret
+
+        else:
+            logger.error("------ Unknown message type: %s", msg_type)
+            raise ValueError(f"Unknown message type: {msg_type}")
+
+        return True, offset
+
+    def parse_log_data(self, logdata, debug=False):
+        """Parse binary log data and print the encoded log messages"""
+        offset = 0
+        still_parsing = True
+
+        while offset < len(logdata) and still_parsing:
+            still_parsing, offset = self.parse_one_msg(logdata, offset)
+
+        return offset
 
-        return True
 
 colorama.init()

scripts/logging/dictionary/log_parser.py

@@ -109,12 +109,20 @@ def main():
     else:
         logger.setLevel(logging.INFO)
 
+    log_parser = parserlib.get_log_parser(args.dbfile, logger)
+
     logdata = read_log_file(args)
     if logdata is None:
         logger.error("ERROR: cannot read log from file: %s, exiting...", args.logfile)
         sys.exit(1)
 
-    parserlib.parser(logdata, args.dbfile, logger)
+    parsed_data_offset = parserlib.parser(logdata, log_parser, logger)
+    if parsed_data_offset != len(logdata):
+        logger.error(
+            'ERROR: Not all data was parsed, %d bytes left unparsed',
+            len(logdata) - parsed_data_offset,
+        )
+        sys.exit(1)
 
 if __name__ == "__main__":
     main()

scripts/logging/dictionary/log_parser_uart.py

@@ -50,14 +50,18 @@ def main():
     else:
         logger.setLevel(logging.INFO)
 
+    log_parser = parserlib.get_log_parser(args.dbfile, logger)
+
     # Parse the log every second from serial port
+    data = b''
     with serial.Serial(args.serialPort, args.baudrate) as ser:
         ser.timeout = 2
         while True:
             size = ser.inWaiting()
             if size:
-                data = ser.read(size)
-                parserlib.parser(data, args.dbfile, logger)
+                data += ser.read(size)
+                parsed_data_offset = parserlib.parser(data, log_parser, logger)
+                data = data[parsed_data_offset:]
             time.sleep(1)
 
 if __name__ == "__main__":

scripts/logging/dictionary/parserlib.py

@@ -13,40 +13,46 @@
 """
 
 import logging
-import sys
 
 import dictionary_parser
 from dictionary_parser.log_database import LogDatabase
 
 
-def parser(logdata, dbfile, logger):
-    """function of serial parser"""
-    # Read from database file
-    database = LogDatabase.read_json_database(dbfile)
+def get_log_parser(dbfile, logger):
+    """Get the log parser for the given database.
 
-    if not isinstance(logger, logging.Logger):
-        raise ValueError("Invalid logger instance. Please configure the logger!")
+    In addition to creating the parser, the function prints general information about the parser.
+    """
+    database = LogDatabase.read_json_database(dbfile)
 
     if database is None:
         logger.error("ERROR: Cannot open database file:  exiting...")
-        sys.exit(1)
-
-    if logdata is None:
-        logger.error("ERROR: cannot read log from file:  exiting...")
-        sys.exit(1)
-
+        raise ValueError(f"Cannot open database file: {dbfile}")
     log_parser = dictionary_parser.get_parser(database)
+
     if log_parser is not None:
         logger.debug("# Build ID: %s", database.get_build_id())
         logger.debug("# Target: %s, %d-bit", database.get_arch(), database.get_tgt_bits())
         if database.is_tgt_little_endian():
             logger.debug("# Endianness: Little")
         else:
             logger.debug("# Endianness: Big")
-
-        ret = log_parser.parse_log_data(logdata)
-        if not ret:
-            logger.error("ERROR: there were error(s) parsing log data")
-            sys.exit(1)
     else:
         logger.error("ERROR: Cannot find a suitable parser matching database version!")
+        raise ValueError("Cannot create parser.")
+
+    return log_parser
+
+
+def parser(logdata, log_parser, logger):
+    """function of serial parser"""
+
+    if not isinstance(logger, logging.Logger):
+        raise ValueError("Invalid logger instance. Please configure the logger!")
+
+    if logdata is None:
+        logger.error("ERROR: cannot read log from file:  exiting...")
+        raise ValueError("Cannot read log data.")
+
+    ret = log_parser.parse_log_data(logdata)
+    return ret