diff --git a/apps/bench.py b/apps/bench.py index b0558b1d..b99cc11a 100644 --- a/apps/bench.py +++ b/apps/bench.py @@ -96,7 +96,7 @@ # ----------------------------------------------------------------------------- def parse_packet(packet): if len(packet) < 1: - print( + logging.info( color(f'!!! Packet too short (got {len(packet)} bytes, need >= 1)', 'red') ) raise ValueError('packet too short') @@ -104,7 +104,7 @@ def parse_packet(packet): try: packet_type = PacketType(packet[0]) except ValueError: - print(color(f'!!! Invalid packet type 0x{packet[0]:02X}', 'red')) + logging.info(color(f'!!! Invalid packet type 0x{packet[0]:02X}', 'red')) raise return (packet_type, packet[1:]) @@ -112,7 +112,7 @@ def parse_packet(packet): def parse_packet_sequence(packet_data): if len(packet_data) < 5: - print( + logging.info( color( f'!!!Packet too short (got {len(packet_data)} bytes, need >= 5)', 'red', @@ -156,7 +156,7 @@ def print_connection(connection): mtu = connection.att_mtu - print( + logging.info( f'{color("@@@ Connection:", "yellow")} ' f'{connection_parameters} ' f'{data_length} ' @@ -267,15 +267,15 @@ def reset(self): pass async def run(self): - print(color('--- Waiting for I/O to be ready...', 'blue')) + logging.info(color('--- Waiting for I/O to be ready...', 'blue')) await self.packet_io.ready.wait() - print(color('--- Go!', 'blue')) + logging.info(color('--- Go!', 'blue')) if self.tx_start_delay: - print(color(f'*** Startup delay: {self.tx_start_delay}', 'blue')) + logging.info(color(f'*** Startup delay: {self.tx_start_delay}', 'blue')) await asyncio.sleep(self.tx_start_delay) - print(color('=== Sending RESET', 'magenta')) + logging.info(color('=== Sending RESET', 'magenta')) await self.packet_io.send_packet(bytes([PacketType.RESET])) self.start_time = time.time() for tx_i in range(self.tx_packet_count): @@ -286,12 +286,12 @@ async def run(self): packet_flags, tx_i, ) + bytes(self.tx_packet_size - 6) - print(color(f'Sending packet {tx_i}: {len(packet)} bytes', 'yellow')) + logging.info(color(f'Sending packet {tx_i}: {len(packet)} bytes', 'yellow')) self.bytes_sent += len(packet) await self.packet_io.send_packet(packet) await self.done.wait() - print(color('=== Done!', 'magenta')) + logging.info(color('=== Done!', 'magenta')) def on_packet_received(self, packet): try: @@ -302,7 +302,7 @@ def on_packet_received(self, packet): if packet_type == PacketType.ACK: elapsed = time.time() - self.start_time average_tx_speed = self.bytes_sent / elapsed - print( + logging.info( color( f'@@@ Received ACK. Speed: average={average_tx_speed:.4f}' f' ({self.bytes_sent} bytes in {elapsed:.2f} seconds)', @@ -316,6 +316,10 @@ def on_packet_received(self, packet): # Receiver # ----------------------------------------------------------------------------- class Receiver: + expected_packet_index: int + start_timestamp: float + last_timestamp: float + def __init__(self, packet_io): self.reset() self.packet_io = packet_io @@ -337,7 +341,7 @@ def on_packet_received(self, packet): now = time.time() if packet_type == PacketType.RESET: - print(color('=== Received RESET', 'magenta')) + logging.info(color('=== Received RESET', 'magenta')) self.reset() self.start_timestamp = now return @@ -346,13 +350,13 @@ def on_packet_received(self, packet): packet_flags, packet_index = parse_packet_sequence(packet_data) except ValueError: return - print( + logging.info( f'<<< Received packet {packet_index}: ' f'flags=0x{packet_flags:02X}, {len(packet)} bytes' ) if packet_index != self.expected_packet_index: - print( + logging.info( color( f'!!! Unexpected packet, expected {self.expected_packet_index} ' f'but received {packet_index}' @@ -364,7 +368,7 @@ def on_packet_received(self, packet): self.bytes_received += len(packet) instant_rx_speed = len(packet) / elapsed_since_last average_rx_speed = self.bytes_received / elapsed_since_start - print( + logging.info( color( f'Speed: instant={instant_rx_speed:.4f}, average={average_rx_speed:.4f}', 'yellow', @@ -380,12 +384,12 @@ def on_packet_received(self, packet): struct.pack('>bbI', PacketType.ACK, packet_flags, packet_index) ) ) - print(color('@@@ Received last packet', 'green')) + logging.info(color('@@@ Received last packet', 'green')) self.done.set() async def run(self): await self.done.wait() - print(color('=== Done!', 'magenta')) + logging.info(color('=== Done!', 'magenta')) # ----------------------------------------------------------------------------- @@ -407,23 +411,23 @@ def reset(self): pass async def run(self): - print(color('--- Waiting for I/O to be ready...', 'blue')) + logging.info(color('--- Waiting for I/O to be ready...', 'blue')) await self.packet_io.ready.wait() - print(color('--- Go!', 'blue')) + logging.info(color('--- Go!', 'blue')) if self.tx_start_delay: - print(color(f'*** Startup delay: {self.tx_start_delay}', 'blue')) + logging.info(color(f'*** Startup delay: {self.tx_start_delay}', 'blue')) await asyncio.sleep(self.tx_start_delay) - print(color('=== Sending RESET', 'magenta')) + logging.info(color('=== Sending RESET', 'magenta')) await self.packet_io.send_packet(bytes([PacketType.RESET])) await self.send_next_ping() await self.done.wait() average_latency = sum(self.latencies) / len(self.latencies) - print(color(f'@@@ Average latency: {average_latency:.2f}')) - print(color('=== Done!', 'magenta')) + logging.info(color(f'@@@ Average latency: {average_latency:.2f}')) + logging.info(color('=== Done!', 'magenta')) async def send_next_ping(self): packet = struct.pack( @@ -434,7 +438,7 @@ async def send_next_ping(self): else 0, self.current_packet_index, ) + bytes(self.tx_packet_size - 6) - print(color(f'Sending packet {self.current_packet_index}', 'yellow')) + logging.info(color(f'Sending packet {self.current_packet_index}', 'yellow')) self.ping_sent_time = time.time() await self.packet_io.send_packet(packet) @@ -454,7 +458,7 @@ def on_packet_received(self, packet): if packet_type == PacketType.ACK: latency = elapsed * 1000 self.latencies.append(latency) - print( + logging.info( color( f'<<< Received ACK [{packet_index}], latency={latency:.2f}ms', 'green', @@ -464,7 +468,7 @@ def on_packet_received(self, packet): if packet_index == self.current_packet_index: self.current_packet_index += 1 else: - print( + logging.info( color( f'!!! Unexpected packet, expected {self.current_packet_index} ' f'but received {packet_index}' @@ -482,6 +486,8 @@ def on_packet_received(self, packet): # Pong # ----------------------------------------------------------------------------- class Pong: + expected_packet_index: int + def __init__(self, packet_io): self.reset() self.packet_io = packet_io @@ -498,7 +504,7 @@ def on_packet_received(self, packet): return if packet_type == PacketType.RESET: - print(color('=== Received RESET', 'magenta')) + logging.info(color('=== Received RESET', 'magenta')) self.reset() return @@ -506,7 +512,7 @@ def on_packet_received(self, packet): packet_flags, packet_index = parse_packet_sequence(packet_data) except ValueError: return - print( + logging.info( color( f'<<< Received packet {packet_index}: ' f'flags=0x{packet_flags:02X}, {len(packet)} bytes', @@ -515,7 +521,7 @@ def on_packet_received(self, packet): ) if packet_index != self.expected_packet_index: - print( + logging.info( color( f'!!! Unexpected packet, expected {self.expected_packet_index} ' f'but received {packet_index}' @@ -535,7 +541,7 @@ def on_packet_received(self, packet): async def run(self): await self.done.wait() - print(color('=== Done!', 'magenta')) + logging.info(color('=== Done!', 'magenta')) # ----------------------------------------------------------------------------- @@ -553,36 +559,36 @@ async def on_connection(self, connection): peer = Peer(connection) if self.att_mtu: - print(color(f'*** Requesting MTU update: {self.att_mtu}', 'blue')) + logging.info(color(f'*** Requesting MTU update: {self.att_mtu}', 'blue')) await peer.request_mtu(self.att_mtu) - print(color('*** Discovering services...', 'blue')) + logging.info(color('*** Discovering services...', 'blue')) await peer.discover_services() speed_services = peer.get_services_by_uuid(SPEED_SERVICE_UUID) if not speed_services: - print(color('!!! Speed Service not found', 'red')) + logging.info(color('!!! Speed Service not found', 'red')) return speed_service = speed_services[0] - print(color('*** Discovering characteristics...', 'blue')) + logging.info(color('*** Discovering characteristics...', 'blue')) await speed_service.discover_characteristics() speed_txs = speed_service.get_characteristics_by_uuid(SPEED_TX_UUID) if not speed_txs: - print(color('!!! Speed TX not found', 'red')) + logging.info(color('!!! Speed TX not found', 'red')) return self.speed_tx = speed_txs[0] speed_rxs = speed_service.get_characteristics_by_uuid(SPEED_RX_UUID) if not speed_rxs: - print(color('!!! Speed RX not found', 'red')) + logging.info(color('!!! Speed RX not found', 'red')) return self.speed_rx = speed_rxs[0] - print(color('*** Subscribing to RX', 'blue')) + logging.info(color('*** Subscribing to RX', 'blue')) await self.speed_rx.subscribe(self.on_packet_received) - print(color('*** Discovery complete', 'blue')) + logging.info(color('*** Discovery complete', 'blue')) connection.on('disconnection', self.on_disconnection) self.ready.set() @@ -634,10 +640,10 @@ def on_disconnection(self, _): def on_rx_subscription(self, _connection, notify_enabled, _indicate_enabled): if notify_enabled: - print(color('*** RX subscription', 'blue')) + logging.info(color('*** RX subscription', 'blue')) self.ready.set() else: - print(color('*** RX un-subscription', 'blue')) + logging.info(color('*** RX un-subscription', 'blue')) self.ready.clear() def on_tx_write(self, _, value): @@ -685,7 +691,7 @@ def on_packet(self, packet): async def send_packet(self, packet): if not self.io_sink: - print(color('!!! No sink, dropping packet', 'red')) + logging.info(color('!!! No sink, dropping packet', 'red')) return # pylint: disable-next=not-callable @@ -715,7 +721,7 @@ async def on_connection(self, connection: Connection) -> None: connection.on('disconnection', self.on_disconnection) # Connect a new L2CAP channel - print(color(f'>>> Opening L2CAP channel on PSM = {self.psm}', 'yellow')) + logging.info(color(f'>>> Opening L2CAP channel on PSM = {self.psm}', 'yellow')) try: l2cap_channel = await connection.create_l2cap_channel( spec=l2cap.LeCreditBasedChannelSpec( @@ -725,9 +731,9 @@ async def on_connection(self, connection: Connection) -> None: mps=self.mps, ) ) - print(color('*** L2CAP channel:', 'cyan'), l2cap_channel) + logging.info(color(f'*** L2CAP channel: {l2cap_channel}', 'cyan')) except Exception as error: - print(color(f'!!! Connection failed: {error}', 'red')) + logging.info(color(f'!!! Connection failed: {error}', 'red')) return l2cap_channel.sink = self.on_packet @@ -740,7 +746,7 @@ def on_disconnection(self, _): pass def on_l2cap_close(self): - print(color('*** L2CAP channel closed', 'red')) + logging.info(color('*** L2CAP channel closed', 'red')) # ----------------------------------------------------------------------------- @@ -766,7 +772,9 @@ def __init__( ), handler=self.on_l2cap_channel, ) - print(color(f'### Listening for L2CAP connection on PSM {psm}', 'yellow')) + logging.info( + color(f'### Listening for L2CAP connection on PSM {psm}', 'yellow') + ) async def on_connection(self, connection): connection.on('disconnection', self.on_disconnection) @@ -775,7 +783,7 @@ def on_disconnection(self, _): pass def on_l2cap_channel(self, l2cap_channel): - print(color('*** L2CAP channel:', 'cyan'), l2cap_channel) + logging.info(color(f'*** L2CAP channel: {l2cap_channel}', 'cyan')) self.io_sink = l2cap_channel.write l2cap_channel.on('close', self.on_l2cap_close) @@ -784,7 +792,7 @@ def on_l2cap_channel(self, l2cap_channel): self.ready.set() def on_l2cap_close(self): - print(color('*** L2CAP channel closed', 'red')) + logging.info(color('*** L2CAP channel closed', 'red')) self.l2cap_channel = None @@ -805,28 +813,28 @@ async def on_connection(self, connection): # Find the channel number if not specified channel = self.channel if channel == 0: - print( + logging.info( color(f'@@@ Discovering channel number from UUID {self.uuid}', 'cyan') ) channel = await find_rfcomm_channel_with_uuid(connection, self.uuid) - print(color(f'@@@ Channel number = {channel}', 'cyan')) + logging.info(color(f'@@@ Channel number = {channel}', 'cyan')) if channel == 0: - print(color('!!! No RFComm service with this UUID found', 'red')) + logging.info(color('!!! No RFComm service with this UUID found', 'red')) await connection.disconnect() return # Create a client and start it - print(color('*** Starting RFCOMM client...', 'blue')) + logging.info(color('*** Starting RFCOMM client...', 'blue')) rfcomm_client = bumble.rfcomm.Client(connection) rfcomm_mux = await rfcomm_client.start() - print(color('*** Started', 'blue')) + logging.info(color('*** Started', 'blue')) - print(color(f'### Opening session for channel {channel}...', 'yellow')) + logging.info(color(f'### Opening session for channel {channel}...', 'yellow')) try: rfcomm_session = await rfcomm_mux.open_dlc(channel) - print(color('### Session open', 'yellow'), rfcomm_session) + logging.info(color(f'### Session open: {rfcomm_session}', 'yellow')) except bumble.core.ConnectionError as error: - print(color(f'!!! Session open failed: {error}', 'red')) + logging.info(color(f'!!! Session open failed: {error}', 'red')) await rfcomm_mux.disconnect() return @@ -856,7 +864,7 @@ def __init__(self, device, channel): # Setup the SDP to advertise this channel device.sdp_service_records = make_sdp_records(channel_number) - print( + logging.info( color( f'### Listening for RFComm connection on channel {channel_number}', 'yellow', @@ -870,7 +878,7 @@ def on_disconnection(self, _): pass def on_dlc(self, dlc): - print(color('*** DLC connected:', 'blue'), dlc) + logging.info(color(f'*** DLC connected: {dlc}', 'blue')) dlc.sink = self.on_packet self.io_sink = dlc.write @@ -936,12 +944,12 @@ def __init__( self.connection_parameter_preferences = None async def run(self): - print(color('>>> Connecting to HCI...', 'green')) + logging.info(color('>>> Connecting to HCI...', 'green')) async with await open_transport_or_link(self.transport) as ( hci_source, hci_sink, ): - print(color('>>> Connected', 'green')) + logging.info(color('>>> Connected', 'green')) central_address = DEFAULT_CENTRAL_ADDRESS self.device = Device.with_hci( @@ -957,7 +965,9 @@ async def run(self): await self.device.set_discoverable(False) await self.device.set_connectable(False) - print(color(f'### Connecting to {self.peripheral_address}...', 'cyan')) + logging.info( + color(f'### Connecting to {self.peripheral_address}...', 'cyan') + ) try: self.connection = await self.device.connect( self.peripheral_address, @@ -965,15 +975,15 @@ async def run(self): transport=BT_BR_EDR_TRANSPORT if self.classic else BT_LE_TRANSPORT, ) except CommandTimeoutError: - print(color('!!! Connection timed out', 'red')) + logging.info(color('!!! Connection timed out', 'red')) return except bumble.core.ConnectionError as error: - print(color(f'!!! Connection error: {error}', 'red')) + logging.info(color(f'!!! Connection error: {error}', 'red')) return except HCI_StatusError as error: - print(color(f'!!! Connection failed: {error.error_name}')) + logging.info(color(f'!!! Connection failed: {error.error_name}')) return - print(color('### Connected', 'cyan')) + logging.info(color('### Connected', 'cyan')) self.connection.listener = self print_connection(self.connection) @@ -984,7 +994,7 @@ async def run(self): # Request a new data length if requested if self.extended_data_length: - print(color('+++ Requesting extended data length', 'cyan')) + logging.info(color('+++ Requesting extended data length', 'cyan')) await self.connection.set_data_length( self.extended_data_length[0], self.extended_data_length[1] ) @@ -992,16 +1002,16 @@ async def run(self): # Authenticate if requested if self.authenticate: # Request authentication - print(color('*** Authenticating...', 'cyan')) + logging.info(color('*** Authenticating...', 'cyan')) await self.connection.authenticate() - print(color('*** Authenticated', 'cyan')) + logging.info(color('*** Authenticated', 'cyan')) # Encrypt if requested if self.encrypt: # Enable encryption - print(color('*** Enabling encryption...', 'cyan')) + logging.info(color('*** Enabling encryption...', 'cyan')) await self.connection.encrypt() - print(color('*** Encryption on', 'cyan')) + logging.info(color('*** Encryption on', 'cyan')) # Set the PHY if requested if self.phy is not None: @@ -1010,7 +1020,7 @@ async def run(self): tx_phys=[self.phy], rx_phys=[self.phy] ) except HCI_Error as error: - print( + logging.info( color( f'!!! Unable to set the PHY: {error.error_name}', 'yellow' ) @@ -1022,7 +1032,7 @@ async def run(self): await asyncio.sleep(DEFAULT_LINGER_TIME) def on_disconnection(self, reason): - print(color(f'!!! Disconnection: reason={reason}', 'red')) + logging.info(color(f'!!! Disconnection: reason={reason}', 'red')) self.connection = None def on_connection_parameters_update(self): @@ -1057,12 +1067,12 @@ def __init__( self.connected = asyncio.Event() async def run(self): - print(color('>>> Connecting to HCI...', 'green')) + logging.info(color('>>> Connecting to HCI...', 'green')) async with await open_transport_or_link(self.transport) as ( hci_source, hci_sink, ): - print(color('>>> Connected', 'green')) + logging.info(color('>>> Connected', 'green')) peripheral_address = DEFAULT_PERIPHERAL_ADDRESS self.device = Device.with_hci( @@ -1082,7 +1092,7 @@ async def run(self): await self.device.start_advertising(auto_restart=True) if self.classic: - print( + logging.info( color( '### Waiting for connection on' f' {self.device.public_address}...', @@ -1090,14 +1100,14 @@ async def run(self): ) ) else: - print( + logging.info( color( f'### Waiting for connection on {peripheral_address}...', 'cyan', ) ) await self.connected.wait() - print(color('### Connected', 'cyan')) + logging.info(color('### Connected', 'cyan')) await self.mode.on_connection(self.connection) await self.role.run() @@ -1119,7 +1129,7 @@ async def stop_being_discoverable_connectable(): # Request a new data length if needed if self.extended_data_length: - print("+++ Requesting extended data length") + logging.info("+++ Requesting extended data length") AsyncRunner.spawn( connection.set_data_length( self.extended_data_length[0], self.extended_data_length[1] @@ -1127,7 +1137,7 @@ async def stop_being_discoverable_connectable(): ) def on_disconnection(self, reason): - print(color(f'!!! Disconnection: reason={reason}', 'red')) + logging.info(color(f'!!! Disconnection: reason={reason}', 'red')) self.connection = None self.role.reset()