Merge branch 'fix-fast-binlog' into 'master'

fix(binlog): Improve error handling and streamline binary log processing

Closes IDFGH-17270

See merge request espressif/esp-idf-monitor!110

Author: peterdragun

esp_idf_monitor/base/binlog.py

@@ -129,63 +129,70 @@ def retrieve_arguments(self, format_str: str, raw_args: bytes) -> List[Union[int
             length = match.group('length') or ''
             specifier = match.group('specifier')
 
-            # **Handling String (%s, %S)**
-            if specifier in 'sS':
-                if self.buffer_hex_log or self.buffer_char_log or self.buffer_hexdump_log:
-                    buffer_len = (
-                        args[-1] if isinstance(args[-1], int) else None
-                    )  # Previous argument is the buffer length
-                    data, data_len = self.retrieve_data(raw_args[i_arg:], buffer_len)
-                    args.append(data)
+            try:
+                # Handling String (%s, %S)
+                if specifier in 'sS':
+                    if self.buffer_hex_log or self.buffer_char_log or self.buffer_hexdump_log:
+                        buffer_len = (
+                            args[-1] if isinstance(args[-1], int) else None
+                        )  # Previous argument is the buffer length
+                        data, data_len = self.retrieve_data(raw_args[i_arg:], buffer_len)
+                        args.append(data)
+                    else:
+                        text, data_len = self.retrieve_string(raw_args[i_arg:])
+                        args.append(text)
+                    i_arg += data_len
+
+                # Handling Floating Point (%f, %e, %g, etc.)
+                elif specifier in 'fFeEgGaA':
+                    arg_format = '>d'
+                    args.append(struct.unpack_from(arg_format, raw_args, i_arg)[0])
+                    i_arg += struct.calcsize(arg_format)
+
+                # Handling Length-Prefixed Integers
+                elif specifier in 'diouxX':
+                    # ESP32 sends only 32-bit or 64-bit values
+                    if length == 'll':  # 64-bit integers
+                        fmt = 'q'
+                    else:  # 32-bit integers
+                        if length == 'h':  # short
+                            fmt = 'h'
+                            i_arg += 2  # padding to 32-bit
+                        elif length == 'hh':  # char
+                            fmt = 'b'
+                            i_arg += 3  # padding to 32-bit
+                        else:  # int
+                            fmt = 'i'
+                    fmt = fmt.lower() if specifier in 'di' else fmt.upper()  # Signed or unsigned
+                    value = struct.unpack_from(f'>{fmt}', raw_args, i_arg)[0]
+                    i_arg += struct.calcsize(fmt)
+                    args.append(value)
+
+                # Handling Pointer (%p)
+                elif specifier == 'p':
+                    arg_format = '>I'
+                    args.append(struct.unpack_from(arg_format, raw_args, i_arg)[0])
+                    i_arg += struct.calcsize(arg_format)
+
+                # Handling Characters (%c)
+                elif specifier == 'c':
+                    i_arg += 3  # padding to 32-bit
+                    arg_format = '>c'
+                    args.append(struct.unpack_from(arg_format, raw_args, i_arg)[0].decode(errors='replace'))
+                    i_arg += struct.calcsize(arg_format)
+
+                # Default: Treat as integer (%d, %i)
                 else:
-                    text, data_len = self.retrieve_string(raw_args[i_arg:])
-                    args.append(text)
-                i_arg += data_len
-
-            # **Handling Floating Point (%f, %e, %g, etc.)**
-            elif specifier in 'fFeEgGaA':
-                arg_format = '>d'
-                args.append(struct.unpack_from(arg_format, raw_args, i_arg)[0])
-                i_arg += struct.calcsize(arg_format)
-
-            # **Handling Length-Prefixed Integers**
-            elif specifier in 'diouxX':
-                # **ESP32 sends only 32-bit or 64-bit values**
-                if length == 'll':  # 64-bit integers
-                    fmt = 'q'
-                else:  # 32-bit integers
-                    if length == 'h':  # short
-                        fmt = 'h'
-                        i_arg += 2
-                    elif length == 'hh':  # char
-                        fmt = 'b'
-                        i_arg += 3
-                    else:  # int
-                        fmt = 'i'
-                fmt = fmt.lower() if specifier in 'di' else fmt.upper()  # Signed or unsigned
-                value = struct.unpack_from(f'>{fmt}', raw_args, i_arg)[0]
-                i_arg += struct.calcsize(fmt)
-                args.append(value)
-
-            # **Handling Pointer (%p)**
-            elif specifier == 'p':
-                arg_format = '>I'
-                args.append(struct.unpack_from(arg_format, raw_args, i_arg)[0])
-                i_arg += struct.calcsize(arg_format)
-
-            # **Handling Characters (%c)**
-            elif specifier == 'c':
-                i_arg += 3
-                arg_format = '>c'
-                args.append(struct.unpack_from(arg_format, raw_args, i_arg)[0].decode(errors='replace'))
-                i_arg += struct.calcsize(arg_format)
-
-            # **Default: Treat as integer (%d, %i)**
-            else:
-                arg_format = '>i'
-                val = struct.unpack_from(arg_format, raw_args, i_arg)[0]
-                args.append(val)
-                i_arg += struct.calcsize(arg_format)
+                    arg_format = '>i'
+                    val = struct.unpack_from(arg_format, raw_args, i_arg)[0]
+                    args.append(val)
+                    i_arg += struct.calcsize(arg_format)
+
+            except struct.error:
+                # Argument data is truncated (e.g. frame cut off mid-transmission).
+                # Return whatever args we managed to unpack rather than crashing.
+                break
+
         return args
 
 
@@ -224,10 +231,20 @@ def crc8(data: bytes) -> int:
             crc &= 0xFF  # Ensure it's within 8 bits
         return crc
 
-    def find_frames(self, data: bytes) -> Tuple[List[bytes], bytes]:
+    @staticmethod
+    def _plausible_frame_start(control: 'Control') -> bool:
+        """Return True if the control word looks like it could be the start of a real
+        binary log frame rather than noise.  Valid ESP log levels are 1-5 and the only
+        defined version is 0; noise bytes (e.g. 0xFF 0xFF) produce level=7 / version=3
+        which we reject so that scan-ahead continues instead of prematurely breaking."""
+        return 1 <= control.level <= 5 and control.version == 0 and control.pkg_len >= 15
+
+    def find_frames(self, data: bytes) -> Tuple[List[bytes], bytes, bytes]:
         frames: List[bytes] = []
+        leaked_chunks: List[bytes] = []
         i = 0
-        idx_of_last_found_pkg = 0
+        idx_after_last_frame = 0
+        idx_partial_frame = None  # start index of a plausible but incomplete frame
 
         while i < len(data):
             if len(data[i:]) < 15:  # Minimal frame len
@@ -237,40 +254,76 @@ def find_frames(self, data: bytes) -> Tuple[List[bytes], bytes]:
                 try:
                     control = Control(data[start_idx + 1 :])
                     if control.pkg_len > len(data[i:]):
-                        break
+                        # Frame extends beyond available data. Only treat it as a
+                        # genuine partial frame (and stop scanning) if the control
+                        # word looks plausible. Noise bytes that happen to start
+                        # with 0x01/0x02 typically have nonsensical level/version
+                        # values, so those are skipped and scanning continues.
+                        if self._plausible_frame_start(control):
+                            idx_partial_frame = start_idx
+                            break
+                        i += 1
+                        continue
                     frame = data[start_idx : start_idx + control.pkg_len]
                     if control.pkg_len != 0 and self.crc8(frame) == 0:
+                        # Collect non-frame bytes before this frame
+                        if start_idx > idx_after_last_frame:
+                            leaked_chunks.append(data[idx_after_last_frame:start_idx])
                         frames.append(frame)
-                        idx_of_last_found_pkg = start_idx + control.pkg_len
+                        idx_after_last_frame = start_idx + control.pkg_len
                         i += control.pkg_len - 1
                     else:
-                        raise ValueError('Invalid binary log; invalid CRC')
+                        # CRC mismatch – skip this byte and try to re-sync
+                        i += 1
+                        continue
                 except (struct.error, IndexError):
-                    # Invalid control structure
-                    raise ValueError('Invalid binary log; invalid control structure')
-            else:
-                raise ValueError('Invalid binary log; invalid start of frame')
+                    # Malformed control structure – skip this byte and try to re-sync
+                    i += 1
+                    continue
+            # Not a recognised start byte – advance and keep scanning
 
             i += 1
-        # Return recognized frames and any remaining unprocessed data
-        return frames, data[idx_of_last_found_pkg:]
 
-    def convert_to_text(self, data: bytes) -> Tuple[List[bytes], bytes]:
+        # Trailing non-frame data (e.g. boot log text after last valid frame)
+        if idx_partial_frame is not None:
+            # Stopped on partial frame: leaked text is from last frame to partial start
+            if idx_partial_frame > idx_after_last_frame:
+                leaked_chunks.append(data[idx_after_last_frame:idx_partial_frame])
+            remaining = data[idx_partial_frame:]
+        elif i < len(data) and self.detected(data[i]):
+            # Remaining bytes start with binary marker; include up to there as leaked
+            if i > idx_after_last_frame:
+                leaked_chunks.append(data[idx_after_last_frame:i])
+            remaining = data[i:]
+        else:
+            # No partial frame; everything after last frame is non-binary
+            if len(data) > idx_after_last_frame:
+                leaked_chunks.append(data[idx_after_last_frame:])
+            remaining = b''
+
+        leaked_text = b''.join(leaked_chunks)
+        return frames, remaining, leaked_text
+
+    def convert_to_text(self, data: bytes) -> Tuple[List[bytes], bytes, bytes]:
         messages: List[bytes] = []
-        frames, incomplete_fragment = self.find_frames(data)
+        frames, incomplete_fragment, leaked_text = self.find_frames(data)
         for pkg_msg in frames:
             elf_path = self.source_of_message(pkg_msg[0])
             msg = Message(self.debug, elf_path, pkg_msg)
             if msg.buffer_hex_log or msg.buffer_char_log or msg.buffer_hexdump_log:
                 messages += self.format_buffer_message(msg)
             else:
                 messages.append(self.format_message(msg))
-        return messages, incomplete_fragment
+        return messages, incomplete_fragment, leaked_text
 
     def format_message(self, message: Message) -> bytes:
-        text_msg = ArgFormatter().c_format(message.format, message.args)
+        try:
+            text_msg = ArgFormatter().c_format(message.format, message.args)
+        except (IndexError, KeyError):
+            # Fewer args were decoded than the format string expects (truncated frame).
+            text_msg = message.format
         level_name = {1: 'E', 2: 'W', 3: 'I', 4: 'D', 5: 'V'}[message.control.level]
-        return f'{level_name} ({message.timestamp}) {message.tag}: {text_msg}\n'.encode('ascii')
+        return f'{level_name} ({message.timestamp}) {message.tag}: {text_msg}\n'.encode()
 
     def format_buffer_message(self, message) -> List[bytes]:
         text_msg: List[bytes] = []

esp_idf_monitor/base/serial_handler.py

@@ -204,22 +204,22 @@ def handle_serial_input(
 
         sp = self.splitdata(data)
         if self.binary_log_detected:
-            try:
-                text_lines, self._last_line_part = self.binlog.convert_to_text(sp[0])
-                for line in text_lines:
+            text_lines, self._last_line_part, leaked_text = self.binlog.convert_to_text(sp[0])
+            for line in text_lines:
+                self.print_colored(line)
+                self.logger.handle_possible_pc_address_in_line(line)
+                self.monitor_cmd_executor.execute_from_log_line(line)
+            if leaked_text:
+                leaked_lines = leaked_text.splitlines(keepends=True) or [b'']
+                if leaked_lines and not (leaked_lines[-1].endswith(b'\n') or leaked_lines[-1].endswith(b'\r')):
+                    incomplete = leaked_lines.pop()
+                    if not self._last_line_part:
+                        self._last_line_part = incomplete
+                for line in leaked_lines:
                     self.print_colored(line)
                     self.logger.handle_possible_pc_address_in_line(line)
                     self.monitor_cmd_executor.execute_from_log_line(line)
-                return
-            except ValueError:
-                # If no valid binary log frames were found, or if we have too much accumulated data
-                # without valid frames, exit binary log mode
-                self.binary_log_detected = False
-                # Process the accumulated data as regular text instead
-                accumulated_data = sp[0] if sp else b''
-                if accumulated_data:
-                    self._last_line_part = accumulated_data
-                    sp = self.splitdata(b'')  # Re-split the data normally
+            return
 
         for line in sp:
             line_strip = line.strip()