From 1cbcc13c35429b06e9d36c55b9ab46df73a8b51a Mon Sep 17 00:00:00 2001 From: Shane Smiskol Date: Mon, 5 Aug 2024 14:51:56 -0700 Subject: [PATCH] use and configure custom logger (#1994) * prepare to log logs * utils * discoverability * forgot --- __init__.py | 1 + python/__init__.py | 46 +++++++++++++++++++++------------------------- python/spi.py | 26 +++++++++++++------------- python/utils.py | 11 +++++++++++ 4 files changed, 46 insertions(+), 38 deletions(-) create mode 100644 python/utils.py diff --git a/__init__.py b/__init__.py index bf487fddcc..8847def082 100644 --- a/__init__.py +++ b/__init__.py @@ -2,6 +2,7 @@ from .python.spi import PandaSpiException, PandaProtocolMismatch, STBootloaderSPIHandle # noqa: F401 from .python.serial import PandaSerial # noqa: F401 from .python.canhandle import CanHandle # noqa: F401 +from .python.utils import logger # noqa: F401 from .python import (Panda, PandaDFU, # noqa: F401 pack_can_buffer, unpack_can_buffer, calculate_checksum, DLC_TO_LEN, LEN_TO_DLC, ALTERNATIVE_EXPERIENCE, CANPACKET_HEAD_SIZE) diff --git a/python/__init__.py b/python/__init__.py index 32a6308dd9..837c8cc605 100644 --- a/python/__init__.py +++ b/python/__init__.py @@ -6,7 +6,6 @@ import struct import hashlib import binascii -import logging from functools import wraps, partial from itertools import accumulate @@ -16,13 +15,10 @@ from .isotp import isotp_send, isotp_recv from .spi import PandaSpiHandle, PandaSpiException, PandaProtocolMismatch from .usb import PandaUsbHandle +from .utils import logger __version__ = '0.0.10' -# setup logging -LOGLEVEL = os.environ.get('LOGLEVEL', 'INFO').upper() -logging.basicConfig(level=LOGLEVEL, format='%(message)s') - CANPACKET_HEAD_SIZE = 0x6 DLC_TO_LEN = [0, 1, 2, 3, 4, 5, 6, 7, 8, 12, 16, 20, 24, 32, 48, 64] LEN_TO_DLC = {length: dlc for (dlc, length) in enumerate(DLC_TO_LEN)} @@ -39,7 +35,7 @@ def pack_can_buffer(arr): snds = [b''] for address, dat, bus in arr: assert len(dat) in LEN_TO_DLC - #logging.debug(" W 0x%x: 0x%s", address, dat.hex()) + #logger.debug(" W 0x%x: 0x%s", address, dat.hex()) extended = 1 if address >= 0x800 else 0 data_len_code = LEN_TO_DLC[len(dat)] @@ -290,7 +286,7 @@ def connect(self, claim=True, wait=False): self._handle_open = True self._mcu_type = self.get_mcu_type() self.health_version, self.can_version, self.can_health_version = self.get_packets_versions() - logging.debug("connected") + logger.debug("connected") # disable openpilot's heartbeat checks if self._disable_checks: @@ -361,11 +357,11 @@ def usb_connect(cls, serial, claim=True): try: this_serial = device.getSerialNumber() except Exception: - logging.exception("failed to get serial number of panda") + logger.exception("failed to get serial number of panda") continue if serial is None or this_serial == serial: - logging.debug("opening device %s %s", this_serial, hex(device.getProductID())) + logger.debug("opening device %s %s", this_serial, hex(device.getProductID())) usb_serial = this_serial bootstub = (device.getProductID() & 0xF0) == 0xe0 @@ -383,7 +379,7 @@ def usb_connect(cls, serial, claim=True): break except Exception: - logging.exception("USB connect error") + logger.exception("USB connect error") usb_handle = None if handle is not None: @@ -411,11 +407,11 @@ def usb_list(cls): if len(serial) == 24: ret.append(serial) else: - logging.warning(f"found device with panda descriptors but invalid serial: {serial}", RuntimeWarning) + logger.warning(f"found device with panda descriptors but invalid serial: {serial}", RuntimeWarning) except Exception: - logging.exception("error connecting to panda") + logger.exception("error connecting to panda") except Exception: - logging.exception("exception while listing pandas") + logger.exception("exception while listing pandas") return ret @classmethod @@ -483,22 +479,22 @@ def flash_static(handle, code, mcu_type): assert last_sector < 7, "Binary too large! Risk of overwriting provisioning chunk." # unlock flash - logging.warning("flash: unlocking") + logger.warning("flash: unlocking") handle.controlWrite(Panda.REQUEST_IN, 0xb1, 0, 0, b'') # erase sectors - logging.warning(f"flash: erasing sectors 1 - {last_sector}") + logger.warning(f"flash: erasing sectors 1 - {last_sector}") for i in range(1, last_sector + 1): handle.controlWrite(Panda.REQUEST_IN, 0xb2, i, 0, b'') # flash over EP2 STEP = 0x10 - logging.warning("flash: flashing") + logger.warning("flash: flashing") for i in range(0, len(code), STEP): handle.bulkWrite(2, code[i:i + STEP]) # reset - logging.warning("flash: resetting") + logger.warning("flash: resetting") try: handle.controlWrite(Panda.REQUEST_IN, 0xd8, 0, 0, b'', expect_disconnect=True) except Exception: @@ -506,13 +502,13 @@ def flash_static(handle, code, mcu_type): def flash(self, fn=None, code=None, reconnect=True): if self.up_to_date(fn=fn): - logging.debug("flash: already up to date") + logger.debug("flash: already up to date") return if not fn: fn = os.path.join(FW_PATH, self._mcu_type.config.app_fn) assert os.path.isfile(fn) - logging.debug("flash: main version is %s", self.get_version()) + logger.debug("flash: main version is %s", self.get_version()) if not self.bootstub: self.reset(enter_bootstub=True) assert(self.bootstub) @@ -522,7 +518,7 @@ def flash(self, fn=None, code=None, reconnect=True): code = f.read() # get version - logging.debug("flash: bootstub version is %s", self.get_version()) + logger.debug("flash: bootstub version is %s", self.get_version()) # do flash Panda.flash_static(self._handle, code, mcu_type=self._mcu_type) @@ -554,7 +550,7 @@ def wait_for_dfu(dfu_serial: str | None, timeout: int | None = None) -> bool: t_start = time.monotonic() dfu_list = PandaDFU.list() while (dfu_serial is None and len(dfu_list) == 0) or (dfu_serial is not None and dfu_serial not in dfu_list): - logging.debug("waiting for DFU...") + logger.debug("waiting for DFU...") time.sleep(0.1) if timeout is not None and (time.monotonic() - t_start) > timeout: return False @@ -566,7 +562,7 @@ def wait_for_panda(serial: str | None, timeout: int) -> bool: t_start = time.monotonic() serials = Panda.list() while (serial is None and len(serials) == 0) or (serial is not None and serial not in serials): - logging.debug("waiting for panda...") + logger.debug("waiting for panda...") time.sleep(0.1) if timeout is not None and (time.monotonic() - t_start) > timeout: return False @@ -806,10 +802,10 @@ def can_send_many(self, arr, timeout=CAN_SEND_TIMEOUT_MS): tx = tx[bs:] if len(tx) == 0: break - logging.error("CAN: PARTIAL SEND MANY, RETRYING") + logger.error("CAN: PARTIAL SEND MANY, RETRYING") break except (usb1.USBErrorIO, usb1.USBErrorOverflow): - logging.error("CAN: BAD SEND MANY, RETRYING") + logger.error("CAN: BAD SEND MANY, RETRYING") def can_send(self, addr, dat, bus, timeout=CAN_SEND_TIMEOUT_MS): self.can_send_many([[addr, dat, bus]], timeout=timeout) @@ -822,7 +818,7 @@ def can_recv(self): dat = self._handle.bulkRead(1, 16384) # Max receive batch size + 2 extra reserve frames break except (usb1.USBErrorIO, usb1.USBErrorOverflow): - logging.error("CAN: BAD RECV, RETRYING") + logger.error("CAN: BAD RECV, RETRYING") time.sleep(0.1) msgs, self.can_rx_overflow_buffer = unpack_can_buffer(self.can_rx_overflow_buffer + dat) return msgs diff --git a/python/spi.py b/python/spi.py index be4f7dcf46..59e9018159 100644 --- a/python/spi.py +++ b/python/spi.py @@ -5,7 +5,6 @@ import math import time import struct -import logging import threading from contextlib import contextmanager from functools import reduce @@ -13,6 +12,7 @@ from .base import BaseHandle, BaseSTBootloaderHandle, TIMEOUT from .constants import McuType, MCU_TYPE_BY_IDCODE, USBPACKET_MAX_SIZE +from .utils import logger try: import spidev @@ -167,23 +167,23 @@ def _wait_for_ack(self, spi, ack_val: int, timeout: int, tx: int, length: int = def _transfer_spidev(self, spi, endpoint: int, data, timeout: int, max_rx_len: int = 1000, expect_disconnect: bool = False) -> bytes: max_rx_len = max(USBPACKET_MAX_SIZE, max_rx_len) - logging.debug("- send header") + logger.debug("- send header") packet = struct.pack(" bytes: - logging.debug("starting transfer: endpoint=%d, max_rx_len=%d", endpoint, max_rx_len) - logging.debug("==============================================") + logger.debug("starting transfer: endpoint=%d, max_rx_len=%d", endpoint, max_rx_len) + logger.debug("==============================================") n = 0 start_time = time.monotonic() exc = PandaSpiException() while (timeout == 0) or (time.monotonic() - start_time) < timeout*1e-3: n += 1 - logging.debug("\ntry #%d", n) + logger.debug("\ntry #%d", n) with self.dev.acquire() as spi: try: return self._transfer_raw(spi, endpoint, data, timeout, max_rx_len, expect_disconnect) except PandaSpiException as e: exc = e - logging.debug("SPI transfer failed, retrying", exc_info=True) + logger.debug("SPI transfer failed, retrying", exc_info=True) raise exc @@ -245,7 +245,7 @@ def get_protocol_version(self) -> bytes: def _get_version(spi) -> bytes: spi.writebytes(vers_str) - logging.debug("- waiting for echo") + logger.debug("- waiting for echo") start = time.monotonic() while True: version_bytes = spi.readbytes(len(vers_str) + 2) @@ -273,7 +273,7 @@ def _get_version(spi) -> bytes: return _get_version(spi) except PandaSpiException as e: exc = e - logging.debug("SPI get protocol version failed, retrying", exc_info=True) + logger.debug("SPI get protocol version failed, retrying", exc_info=True) raise exc # libusb1 functions @@ -378,7 +378,7 @@ def _cmd(self, cmd: int, data: list[bytes] | None = None, read_bytes: int = 0, p return self._cmd_no_retry(cmd, data, read_bytes, predata) except PandaSpiException as e: exc = e - logging.debug("SPI transfer failed, %d retries left", MAX_XFER_RETRY_COUNT - n - 1, exc_info=True) + logger.debug("SPI transfer failed, %d retries left", MAX_XFER_RETRY_COUNT - n - 1, exc_info=True) raise exc def _checksum(self, data: bytes) -> bytes: diff --git a/python/utils.py b/python/utils.py new file mode 100644 index 0000000000..55181e08b1 --- /dev/null +++ b/python/utils.py @@ -0,0 +1,11 @@ +import os +import logging + +# set up logging +LOGLEVEL = os.environ.get('LOGLEVEL', 'INFO').upper() +logger = logging.getLogger('panda') +logger.setLevel(LOGLEVEL) + +handler = logging.StreamHandler() +handler.setFormatter(logging.Formatter('%(message)s')) +logger.addHandler(handler)