From 9d6a2dd03109091757849f3b1f33c3d86fa8cf04 Mon Sep 17 00:00:00 2001 From: Tim Camise Date: Thu, 7 Dec 2023 15:14:59 -0800 Subject: [PATCH] Always debug log to file (#453) * Always log bluetoothctl communication to file --- .../open_gopro/ble/adapters/bleak_wrapper.py | 67 ++++++++++--------- .../open_gopro/demos/gui/livestream.py | 4 +- .../open_gopro/logger.py | 49 +++++++------- 3 files changed, 63 insertions(+), 57 deletions(-) diff --git a/demos/python/sdk_wireless_camera_control/open_gopro/ble/adapters/bleak_wrapper.py b/demos/python/sdk_wireless_camera_control/open_gopro/ble/adapters/bleak_wrapper.py index 86cfca46..fefd5158 100644 --- a/demos/python/sdk_wireless_camera_control/open_gopro/ble/adapters/bleak_wrapper.py +++ b/demos/python/sdk_wireless_camera_control/open_gopro/ble/adapters/bleak_wrapper.py @@ -6,7 +6,8 @@ import asyncio import logging import platform -import sys +import tempfile +from pathlib import Path from typing import Any, Callable, Optional, Pattern import bleak @@ -254,37 +255,41 @@ async def pair(self, handle: bleak.BleakClient) -> None: handle (bleak.BleakClient): Device to pair to """ logger.debug("Attempting to pair...") + if (OS := platform.system()) == "Linux": - logger.info("Pairing with bluetoothctl") - # Manually control bluetoothctl on Linux - bluetoothctl = pexpect.spawn("bluetoothctl") - if logger.level == logging.DEBUG: - bluetoothctl.logfile = sys.stdout.buffer - bluetoothctl.expect("Agent registered") - # Get the version - bluetoothctl.sendline("version") - bluetoothctl.expect(r"Version") - bluetoothctl.expect(r"\n") - version = Version(bluetoothctl.before.decode("utf-8").strip()) - # First see if we are already paired - if version >= Version("5.66"): - bluetoothctl.sendline("devices Paired") - bluetoothctl.expect("devices Paired") - else: - bluetoothctl.sendline("paired-devices") - bluetoothctl.expect("paired-devices") - bluetoothctl.expect(r"#") - for device in bluetoothctl.before.decode("utf-8").splitlines(): - if "Device" in device and device.split()[1] == handle.address: - break # The device is already paired - else: - # We're not paired so do it now - bluetoothctl.sendline(f"pair {handle.address}") - if (match := bluetoothctl.expect(["Accept pairing", "Pairing successful"])) == 0: - bluetoothctl.sendline("yes") - bluetoothctl.expect("Pairing successful") - elif match == 1: # We received pairing successful so nothing else to do - pass + temp_file = Path(tempfile.gettempdir()) / "pexpect.log" + with open(temp_file, "wb") as fp: + logger.info("Pairing with bluetoothctl") + # Manually control bluetoothctl on Linux + bluetoothctl = pexpect.spawn("bluetoothctl") + bluetoothctl.logfile = fp + bluetoothctl.expect("Agent registered") + # Get the version + bluetoothctl.sendline("version") + bluetoothctl.expect(r"Version") + bluetoothctl.expect(r"\n") + version = Version(bluetoothctl.before.decode("utf-8").strip()) + # First see if we are already paired + if version >= Version("5.66"): + bluetoothctl.sendline("devices Paired") + bluetoothctl.expect("devices Paired") + else: + bluetoothctl.sendline("paired-devices") + bluetoothctl.expect("paired-devices") + bluetoothctl.expect(r"#") + for device in bluetoothctl.before.decode("utf-8").splitlines(): + if "Device" in device and device.split()[1] == handle.address: + break # The device is already paired + else: + # We're not paired so do it now + bluetoothctl.sendline(f"pair {handle.address}") + if (match := bluetoothctl.expect(["Accept pairing", "Pairing successful"])) == 0: + bluetoothctl.sendline("yes") + bluetoothctl.expect("Pairing successful") + elif match == 1: # We received pairing successful so nothing else to do + pass + + logger.debug(temp_file.read_bytes().decode("utf-8")) elif OS == "Darwin": # No pairing on Mac diff --git a/demos/python/sdk_wireless_camera_control/open_gopro/demos/gui/livestream.py b/demos/python/sdk_wireless_camera_control/open_gopro/demos/gui/livestream.py index 31ca5b16..32735bc5 100644 --- a/demos/python/sdk_wireless_camera_control/open_gopro/demos/gui/livestream.py +++ b/demos/python/sdk_wireless_camera_control/open_gopro/demos/gui/livestream.py @@ -56,7 +56,7 @@ async def wait_for_livestream_start(_: Any, update: proto.NotifyLiveStreamStatus console.print("[yellow]Starting livestream") assert (await gopro.ble_command.set_shutter(shutter=Params.Toggle.ENABLE)).ok - console.print("Livestream is now streaming and should be available for viewing.") + console.print("[yellow]Livestream is now streaming and should be available for viewing.") await ainput("Press enter to stop livestreaming...\n") await gopro.ble_command.set_shutter(shutter=Params.Toggle.DISABLE) @@ -80,7 +80,7 @@ def parse_arguments() -> argparse.Namespace: default=proto.EnumWindowSize.WINDOW_SIZE_720, ) parser.add_argument( - "--fov", help="Field of View.", choices=list(proto.EnumLens.values()), default=proto.EnumLens.LENS_WIDE + "--fov", help="Field of View.", choices=list(proto.EnumLens.values()), default=proto.EnumLens.LENS_LINEAR ) return add_cli_args_and_parse(parser, wifi=False) diff --git a/demos/python/sdk_wireless_camera_control/open_gopro/logger.py b/demos/python/sdk_wireless_camera_control/open_gopro/logger.py index edccacfc..6c863180 100644 --- a/demos/python/sdk_wireless_camera_control/open_gopro/logger.py +++ b/demos/python/sdk_wireless_camera_control/open_gopro/logger.py @@ -39,29 +39,29 @@ def __init__( self, logger: Any, output: Path | None = None, - modules: dict[str, int] | None = None, + modules: list[str] | None = None, ) -> None: - self.modules = { - "open_gopro.gopro_base": logging.DEBUG, # TRACE for raw HTTP responses - "open_gopro.gopro_wired": logging.DEBUG, # TRACE for concurrency debugging - "open_gopro.gopro_wireless": logging.DEBUG, # TRACE for concurrency debugging - "open_gopro.api.builders": logging.DEBUG, - "open_gopro.api.http_commands": logging.DEBUG, - "open_gopro.api.ble_commands": logging.DEBUG, - "open_gopro.communication_client": logging.DEBUG, - "open_gopro.ble.adapters.bleak_wrapper": logging.INFO, # DEBUG for pexpect communication - "open_gopro.ble.client": logging.DEBUG, - "open_gopro.wifi.adapters.wireless": logging.DEBUG, - "open_gopro.wifi.mdns_scanner": logging.DEBUG, - "open_gopro.responses": logging.DEBUG, - "open_gopro.util": logging.DEBUG, - "bleak": logging.DEBUG, - "urllib3": logging.DEBUG, - "http.client": logging.DEBUG, - } + self.modules = [ + "open_gopro.gopro_base", + "open_gopro.gopro_wired", + "open_gopro.gopro_wireless", + "open_gopro.api.builders", + "open_gopro.api.http_commands", + "open_gopro.api.ble_commands", + "open_gopro.communication_client", + "open_gopro.ble.adapters.bleak_wrapper", + "open_gopro.ble.client", + "open_gopro.wifi.adapters.wireless", + "open_gopro.wifi.mdns_scanner", + "open_gopro.responses", + "open_gopro.util", + "bleak", + "urllib3", + "http.client", + ] self.logger = logger - self.modules = {**self.modules, **modules} if modules else self.modules + self.modules = modules or self.modules self.handlers: list[logging.Handler] = [] # monkey-patch a `print` global into the http.client module; all calls to @@ -78,7 +78,8 @@ def __init__( datefmt="%H:%M:%S", ) self.file_handler.setFormatter(file_formatter) - self.file_handler.setLevel(logging.TRACE) # type: ignore # pylint: disable=no-member + # Set to TRACE for concurrency debugging + self.file_handler.setLevel(logging.DEBUG) logger.addHandler(self.file_handler) self.addLoggingHandler(self.file_handler) else: @@ -121,9 +122,9 @@ def addLoggingHandler(self, handler: logging.Handler) -> None: self.handlers.append(handler) # Enable / disable logging in modules - for module, level in self.modules.items(): + for module in self.modules: l = logging.getLogger(module) - l.setLevel(level) + l.setLevel(logging.TRACE) # type: ignore l.addHandler(handler) # From https://stackoverflow.com/questions/2183233/how-to-add-a-custom-loglevel-to-pythons-logging-facility/35804945#35804945 @@ -203,7 +204,7 @@ def build_log_rx_str(stringable: Any, asynchronous: bool = False) -> str: def setup_logging( - base: logging.Logger | str, output: Path | None = None, modules: dict[str, int] | None = None + base: logging.Logger | str, output: Path | None = None, modules: list[str] | None = None ) -> logging.Logger: """Configure the GoPro modules for logging and get a logger that can be used by the application