use and configure custom logger (commaai#1994)

* prepare to log logs * utils * discoverability * forgot
dzid26 · Aug 5, 2024 · 1cbcc13 · 1cbcc13
1 parent 3c1def1
commit 1cbcc13
Show file tree

Hide file tree

Showing 4 changed files with 46 additions and 38 deletions.
diff --git 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
@@ -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,36 +479,36 @@ 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:
       pass
 
   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
@@ -5,14 +5,14 @@
 import math
 import time
 import struct
-import logging
 import threading
 from contextlib import contextmanager
 from functools import reduce
 from collections.abc import Callable
 
 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("<BBHH", SYNC, endpoint, len(data), max_rx_len)
     packet += bytes([self._calc_checksum(packet), ])
     spi.xfer2(packet)
 
-    logging.debug("- waiting for header ACK")
+    logger.debug("- waiting for header ACK")
     self._wait_for_ack(spi, HACK, MIN_ACK_TIMEOUT_MS, 0x11)
 
-    logging.debug("- sending data")
+    logger.debug("- sending data")
     packet = bytes([*data, self._calc_checksum(data)])
     spi.xfer2(packet)
 
     if expect_disconnect:
-      logging.debug("- expecting disconnect, returning")
+      logger.debug("- expecting disconnect, returning")
       return b""
     else:
-      logging.debug("- waiting for data ACK")
+      logger.debug("- waiting for data ACK")
       preread_len = USBPACKET_MAX_SIZE + 1  # read enough for a controlRead
       dat = self._wait_for_ack(spi, DACK, timeout, 0x13, length=3 + preread_len)
 
@@ -222,21 +222,21 @@ def _transfer_kernel_driver(self, spi, endpoint: int, data, timeout: int, max_rx
     return bytes(self.rx_buf[:ret])
 
   def _transfer(self, endpoint: int, data, timeout: int, max_rx_len: int = 1000, expect_disconnect: bool = False) -> 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
@@ -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)