From f2d601f411484bcc16495f01f54a30d08ed27590 Mon Sep 17 00:00:00 2001 From: Gilles Boccon-Gibod Date: Tue, 27 Feb 2024 16:40:37 -0800 Subject: [PATCH 1/2] show timestamps from snoop logs --- apps/show.py | 75 ++++++++++++++++++++++++++++++-------- bumble/helpers.py | 27 +++++++++++--- bumble/transport/common.py | 2 + 3 files changed, 83 insertions(+), 21 deletions(-) diff --git a/apps/show.py b/apps/show.py index f849e3a7..0486cbfb 100644 --- a/apps/show.py +++ b/apps/show.py @@ -15,7 +15,11 @@ # ----------------------------------------------------------------------------- # Imports # ----------------------------------------------------------------------------- +import datetime +import logging +import os import struct + import click from bumble.colors import color @@ -24,6 +28,14 @@ from bumble.helpers import PacketTracer +# ----------------------------------------------------------------------------- +# Logging +# ----------------------------------------------------------------------------- +logger = logging.getLogger(__name__) + + +# ----------------------------------------------------------------------------- +# Classes # ----------------------------------------------------------------------------- class SnoopPacketReader: ''' @@ -36,12 +48,18 @@ class SnoopPacketReader: DATALINK_BSCP = 1003 DATALINK_H5 = 1004 + IDENTIFICATION_PATTERN = b'btsnoop\0' + TIMESTAMP_ANCHOR = datetime.datetime(2000, 1, 1) + TIMESTAMP_DELTA = 0x00E03AB44A676000 + ONE_MICROSECOND = datetime.timedelta(microseconds=1) + def __init__(self, source): self.source = source + self.at_end = False # Read the header identification_pattern = source.read(8) - if identification_pattern.hex().lower() != '6274736e6f6f7000': + if identification_pattern != self.IDENTIFICATION_PATTERN: raise ValueError( 'not a valid snoop file, unexpected identification pattern' ) @@ -55,19 +73,32 @@ def next_packet(self): # Read the record header header = self.source.read(24) if len(header) < 24: - return (0, None) + self.at_end = True + return (None, 0, None) + + # Parse the header ( original_length, included_length, packet_flags, _cumulative_drops, - _timestamp_seconds, - _timestamp_microsecond, - ) = struct.unpack('>IIIIII', header) + timestamp, + ) = struct.unpack('>IIIIQ', header) - # Abort on truncated packets + # Skip truncated packets if original_length != included_length: - return (0, None) + print( + color( + f"!!! truncated packet ({included_length}/{original_length})", "red" + ) + ) + self.source.read(included_length) + return (None, 0, None) + + # Convert the timestamp to a datetime object. + ts_dt = self.TIMESTAMP_ANCHOR + datetime.timedelta( + microseconds=timestamp - self.TIMESTAMP_DELTA + ) if self.data_link_type == self.DATALINK_H1: # The packet is un-encapsulated, look at the flags to figure out its type @@ -89,7 +120,17 @@ def next_packet(self): bytes([packet_type]) + self.source.read(included_length), ) - return (packet_flags & 1, self.source.read(included_length)) + return (ts_dt, packet_flags & 1, self.source.read(included_length)) + + +# ----------------------------------------------------------------------------- +class Printer: + def __init__(self): + self.index = 0 + + def print(self, message: str) -> None: + self.index += 1 + print(f"[{self.index}]{message}") # ----------------------------------------------------------------------------- @@ -122,24 +163,28 @@ def main(format, vendors, filename): packet_reader = PacketReader(input) def read_next_packet(): - return (0, packet_reader.next_packet()) + return (None, 0, packet_reader.next_packet()) else: packet_reader = SnoopPacketReader(input) read_next_packet = packet_reader.next_packet - tracer = PacketTracer(emit_message=print) + printer = Printer() + tracer = PacketTracer(emit_message=printer.print) - while True: + while not packet_reader.at_end: try: - (direction, packet) = read_next_packet() - if packet is None: - break - tracer.trace(hci.HCI_Packet.from_bytes(packet), direction) + (timestamp, direction, packet) = read_next_packet() + if packet: + tracer.trace(hci.HCI_Packet.from_bytes(packet), direction, timestamp) + else: + printer.print(color("[TRUNCATED]", "red")) except Exception as error: + logger.exception() print(color(f'!!! {error}', 'red')) # ----------------------------------------------------------------------------- if __name__ == '__main__': + logging.basicConfig(level=os.environ.get('BUMBLE_LOGLEVEL', 'WARNING').upper()) main() # pylint: disable=no-value-for-parameter diff --git a/bumble/helpers.py b/bumble/helpers.py index c6a6d2ec..80a376ef 100644 --- a/bumble/helpers.py +++ b/bumble/helpers.py @@ -18,6 +18,7 @@ from __future__ import annotations from collections.abc import Callable, MutableMapping +import datetime from typing import cast, Any, Optional import logging @@ -66,12 +67,13 @@ rfcomm.RFCOMM_PSM: 'RFCOMM', sdp.SDP_PSM: 'SDP', avdtp.AVDTP_PSM: 'AVDTP', - avctp.AVCTP_PSM: 'AVCTP' + avctp.AVCTP_PSM: 'AVCTP', # TODO: add more PSM values } AVCTP_PID_NAMES = {avrcp.AVRCP_PID: 'AVRCP'} + # ----------------------------------------------------------------------------- class PacketTracer: class AclStream: @@ -207,6 +209,7 @@ def __init__(self, label: str, emit_message: Callable[..., None]) -> None: self.label = label self.emit_message = emit_message self.acl_streams = {} # ACL streams, by connection handle + self.packet_timestamp: Optional[datetime.datetime] = None def start_acl_stream(self, connection_handle: int) -> PacketTracer.AclStream: logger.info( @@ -234,7 +237,10 @@ def end_acl_stream(self, connection_handle: int) -> None: # Let the other forwarder know so it can cleanup its stream as well self.peer.end_acl_stream(connection_handle) - def on_packet(self, packet: HCI_Packet) -> None: + def on_packet( + self, timestamp: Optional[datetime.datetime], packet: HCI_Packet + ) -> None: + self.packet_timestamp = timestamp self.emit(packet) if packet.hci_packet_type == HCI_ACL_DATA_PACKET: @@ -254,13 +260,22 @@ def on_packet(self, packet: HCI_Packet) -> None: ) def emit(self, message: Any) -> None: - self.emit_message(f'[{self.label}] {message}') + if self.packet_timestamp: + prefix = f"[{self.packet_timestamp.strftime('%Y-%m-%d %H:%M:%S.%f')}]" + else: + prefix = "" + self.emit_message(f'{prefix}[{self.label}] {message}') - def trace(self, packet: HCI_Packet, direction: int = 0) -> None: + def trace( + self, + packet: HCI_Packet, + direction: int = 0, + timestamp: Optional[datetime.datetime] = None, + ) -> None: if direction == 0: - self.host_to_controller_analyzer.on_packet(packet) + self.host_to_controller_analyzer.on_packet(timestamp, packet) else: - self.controller_to_host_analyzer.on_packet(packet) + self.controller_to_host_analyzer.on_packet(timestamp, packet) def __init__( self, diff --git a/bumble/transport/common.py b/bumble/transport/common.py index f767f54f..ef35c9f1 100644 --- a/bumble/transport/common.py +++ b/bumble/transport/common.py @@ -168,11 +168,13 @@ class PacketReader: def __init__(self, source: io.BufferedReader) -> None: self.source = source + self.at_end = False def next_packet(self) -> Optional[bytes]: # Get the packet type packet_type = self.source.read(1) if len(packet_type) != 1: + self.at_end = True return None # Get the packet info based on its type From 38981cefa1da23bd4acaf3b7a4c323e7ab6e6707 Mon Sep 17 00:00:00 2001 From: Gilles Boccon-Gibod Date: Wed, 28 Feb 2024 11:46:35 -0800 Subject: [PATCH 2/2] pad index field --- apps/show.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apps/show.py b/apps/show.py index 0486cbfb..97640a37 100644 --- a/apps/show.py +++ b/apps/show.py @@ -130,7 +130,7 @@ def __init__(self): def print(self, message: str) -> None: self.index += 1 - print(f"[{self.index}]{message}") + print(f"[{self.index:8}]{message}") # -----------------------------------------------------------------------------