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, source_id = 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"""
@@ -347,27 +359,41 @@ def parse_log_data(self, logdata, debug=False):
         offset = 0
 
         while offset < len(logdata):
+            if offset + struct.calcsize(self.fmt_msg_type) > len(logdata):
+                return offset
+
             # 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:
+
+                if offset + struct.calcsize(self.fmt_dropped_cnt) > len(logdata):
+                    return offset
+                offset += struct.calcsize(self.fmt_msg_type)
+
                 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:
+
+                if ((offset + self.get_full_msg_hdr_size() > len(logdata)) or
+                    (offset + self.get_normal_msg_size(logdata, offset) > len(logdata))):
+                    return offset
+
+                offset += struct.calcsize(self.fmt_msg_type)
+
                 ret = self.parse_one_normal_msg(logdata, offset)
                 if ret is None:
-                    return False
+                    raise ValueError("Error parsing normal log message")
 
                 offset = ret
 
             else:
                 logger.error("------ Unknown message type: %s", msg_type)
-                return False
+                raise ValueError(f"Unknown message type: {msg_type}")
 
-        return True
+        return offset
 
 colorama.init()

scripts/logging/dictionary/dictionary_parser/log_parser_v3.py

@@ -260,6 +260,16 @@ 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, source_id = 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"""
@@ -356,27 +366,42 @@ def parse_log_data(self, logdata, debug=False):
         offset = 0
 
         while offset < len(logdata):
+            if offset + struct.calcsize(self.fmt_msg_type) > len(logdata):
+                return offset
+
             # 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:
+
+                if offset + struct.calcsize(self.fmt_dropped_cnt) > len(logdata):
+                    return offset
+
+                offset += struct.calcsize(self.fmt_msg_type)
+
                 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:
+
+                if ((offset + self.get_full_msg_hdr_size() > len(logdata)) or
+                    (offset + self.get_normal_msg_size(logdata, offset) > len(logdata))):
+                    return offset
+
+                offset += struct.calcsize(self.fmt_msg_type)
+
                 ret = self.parse_one_normal_msg(logdata, offset)
                 if ret is None:
-                    return False
+                    raise ValueError("Error parsing normal log message")
 
                 offset = ret
 
             else:
                 logger.error("------ Unknown message type: %s", msg_type)
-                return False
+                raise ValueError(f"Unknown message type: {msg_type}")
 
-        return True
+        return offset
 
 colorama.init()

scripts/logging/dictionary/log_parser.py

@@ -109,12 +109,18 @@ def main():
     else:
         logger.setLevel(logging.INFO)
 
+    database = parserlib.get_database(args.dbfile)
+    log_parser = parserlib.get_log_parser(database, 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, database, 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,19 @@ def main():
     else:
         logger.setLevel(logging.INFO)
 
+    database = parserlib.get_database(args.dbfile)
+    log_parser = parserlib.get_log_parser(database, 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, database, log_parser, logger)
+                data = data[parsed_data_offset:]
             time.sleep(1)
 
 if __name__ == "__main__":

scripts/logging/dictionary/parserlib.py

@@ -19,22 +19,23 @@
 from dictionary_parser.log_database import LogDatabase
 
 
-def parser(logdata, dbfile, logger):
-    """function of serial parser"""
+def get_database(dbfile):
+    """Create a database out of the JSON file."""
     # Read from database file
     database = LogDatabase.read_json_database(dbfile)
 
-    if not isinstance(logger, logging.Logger):
-        raise ValueError("Invalid logger instance. Please configure the logger!")
-
     if database is None:
         logger.error("ERROR: Cannot open database file:  exiting...")
-        sys.exit(1)
+        raise ValueError(f"Cannot open database file: {dbfile}")
 
-    if logdata is None:
-        logger.error("ERROR: cannot read log from file:  exiting...")
-        sys.exit(1)
+    return database
+
+
+def get_log_parser(database, logger):
+    """Get the log parser for the given database.
 
+    In addition to creating the parser, the function prints general information about the parser.
+    """
     log_parser = dictionary_parser.get_parser(database)
     if log_parser is not None:
         logger.debug("# Build ID: %s", database.get_build_id())
@@ -43,10 +44,22 @@ def parser(logdata, dbfile, logger):
             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(f"Cannot create parser.")
+
+    return log_parser
+
+
+def parser(logdata, database, 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