use and configure custom logger (#1994)

* prepare to log logs

* utils

* discoverability

* forgot
This commit is contained in:
Shane Smiskol
2024-08-05 14:51:56 -07:00
committed by GitHub
parent 3c1def1cc5
commit 1cbcc13c35
4 changed files with 46 additions and 38 deletions

View File

@@ -2,6 +2,7 @@ from .python.constants import McuType, BASEDIR, FW_PATH, USBPACKET_MAX_SIZE # n
from .python.spi import PandaSpiException, PandaProtocolMismatch, STBootloaderSPIHandle # noqa: F401 from .python.spi import PandaSpiException, PandaProtocolMismatch, STBootloaderSPIHandle # noqa: F401
from .python.serial import PandaSerial # noqa: F401 from .python.serial import PandaSerial # noqa: F401
from .python.canhandle import CanHandle # noqa: F401 from .python.canhandle import CanHandle # noqa: F401
from .python.utils import logger # noqa: F401
from .python import (Panda, PandaDFU, # noqa: F401 from .python import (Panda, PandaDFU, # noqa: F401
pack_can_buffer, unpack_can_buffer, calculate_checksum, pack_can_buffer, unpack_can_buffer, calculate_checksum,
DLC_TO_LEN, LEN_TO_DLC, ALTERNATIVE_EXPERIENCE, CANPACKET_HEAD_SIZE) DLC_TO_LEN, LEN_TO_DLC, ALTERNATIVE_EXPERIENCE, CANPACKET_HEAD_SIZE)

View File

@@ -6,7 +6,6 @@ import usb1
import struct import struct
import hashlib import hashlib
import binascii import binascii
import logging
from functools import wraps, partial from functools import wraps, partial
from itertools import accumulate from itertools import accumulate
@@ -16,13 +15,10 @@ from .dfu import PandaDFU
from .isotp import isotp_send, isotp_recv from .isotp import isotp_send, isotp_recv
from .spi import PandaSpiHandle, PandaSpiException, PandaProtocolMismatch from .spi import PandaSpiHandle, PandaSpiException, PandaProtocolMismatch
from .usb import PandaUsbHandle from .usb import PandaUsbHandle
from .utils import logger
__version__ = '0.0.10' __version__ = '0.0.10'
# setup logging
LOGLEVEL = os.environ.get('LOGLEVEL', 'INFO').upper()
logging.basicConfig(level=LOGLEVEL, format='%(message)s')
CANPACKET_HEAD_SIZE = 0x6 CANPACKET_HEAD_SIZE = 0x6
DLC_TO_LEN = [0, 1, 2, 3, 4, 5, 6, 7, 8, 12, 16, 20, 24, 32, 48, 64] 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)} LEN_TO_DLC = {length: dlc for (dlc, length) in enumerate(DLC_TO_LEN)}
@@ -39,7 +35,7 @@ def pack_can_buffer(arr):
snds = [b''] snds = [b'']
for address, dat, bus in arr: for address, dat, bus in arr:
assert len(dat) in LEN_TO_DLC 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 extended = 1 if address >= 0x800 else 0
data_len_code = LEN_TO_DLC[len(dat)] data_len_code = LEN_TO_DLC[len(dat)]
@@ -290,7 +286,7 @@ class Panda:
self._handle_open = True self._handle_open = True
self._mcu_type = self.get_mcu_type() self._mcu_type = self.get_mcu_type()
self.health_version, self.can_version, self.can_health_version = self.get_packets_versions() 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 # disable openpilot's heartbeat checks
if self._disable_checks: if self._disable_checks:
@@ -361,11 +357,11 @@ class Panda:
try: try:
this_serial = device.getSerialNumber() this_serial = device.getSerialNumber()
except Exception: except Exception:
logging.exception("failed to get serial number of panda") logger.exception("failed to get serial number of panda")
continue continue
if serial is None or this_serial == serial: 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 usb_serial = this_serial
bootstub = (device.getProductID() & 0xF0) == 0xe0 bootstub = (device.getProductID() & 0xF0) == 0xe0
@@ -383,7 +379,7 @@ class Panda:
break break
except Exception: except Exception:
logging.exception("USB connect error") logger.exception("USB connect error")
usb_handle = None usb_handle = None
if handle is not None: if handle is not None:
@@ -411,11 +407,11 @@ class Panda:
if len(serial) == 24: if len(serial) == 24:
ret.append(serial) ret.append(serial)
else: 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: except Exception:
logging.exception("error connecting to panda") logger.exception("error connecting to panda")
except Exception: except Exception:
logging.exception("exception while listing pandas") logger.exception("exception while listing pandas")
return ret return ret
@classmethod @classmethod
@@ -483,22 +479,22 @@ class Panda:
assert last_sector < 7, "Binary too large! Risk of overwriting provisioning chunk." assert last_sector < 7, "Binary too large! Risk of overwriting provisioning chunk."
# unlock flash # unlock flash
logging.warning("flash: unlocking") logger.warning("flash: unlocking")
handle.controlWrite(Panda.REQUEST_IN, 0xb1, 0, 0, b'') handle.controlWrite(Panda.REQUEST_IN, 0xb1, 0, 0, b'')
# erase sectors # 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): for i in range(1, last_sector + 1):
handle.controlWrite(Panda.REQUEST_IN, 0xb2, i, 0, b'') handle.controlWrite(Panda.REQUEST_IN, 0xb2, i, 0, b'')
# flash over EP2 # flash over EP2
STEP = 0x10 STEP = 0x10
logging.warning("flash: flashing") logger.warning("flash: flashing")
for i in range(0, len(code), STEP): for i in range(0, len(code), STEP):
handle.bulkWrite(2, code[i:i + STEP]) handle.bulkWrite(2, code[i:i + STEP])
# reset # reset
logging.warning("flash: resetting") logger.warning("flash: resetting")
try: try:
handle.controlWrite(Panda.REQUEST_IN, 0xd8, 0, 0, b'', expect_disconnect=True) handle.controlWrite(Panda.REQUEST_IN, 0xd8, 0, 0, b'', expect_disconnect=True)
except Exception: except Exception:
@@ -506,13 +502,13 @@ class Panda:
def flash(self, fn=None, code=None, reconnect=True): def flash(self, fn=None, code=None, reconnect=True):
if self.up_to_date(fn=fn): if self.up_to_date(fn=fn):
logging.debug("flash: already up to date") logger.debug("flash: already up to date")
return return
if not fn: if not fn:
fn = os.path.join(FW_PATH, self._mcu_type.config.app_fn) fn = os.path.join(FW_PATH, self._mcu_type.config.app_fn)
assert os.path.isfile(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: if not self.bootstub:
self.reset(enter_bootstub=True) self.reset(enter_bootstub=True)
assert(self.bootstub) assert(self.bootstub)
@@ -522,7 +518,7 @@ class Panda:
code = f.read() code = f.read()
# get version # get version
logging.debug("flash: bootstub version is %s", self.get_version()) logger.debug("flash: bootstub version is %s", self.get_version())
# do flash # do flash
Panda.flash_static(self._handle, code, mcu_type=self._mcu_type) Panda.flash_static(self._handle, code, mcu_type=self._mcu_type)
@@ -554,7 +550,7 @@ class Panda:
t_start = time.monotonic() t_start = time.monotonic()
dfu_list = PandaDFU.list() 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): 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) time.sleep(0.1)
if timeout is not None and (time.monotonic() - t_start) > timeout: if timeout is not None and (time.monotonic() - t_start) > timeout:
return False return False
@@ -566,7 +562,7 @@ class Panda:
t_start = time.monotonic() t_start = time.monotonic()
serials = Panda.list() serials = Panda.list()
while (serial is None and len(serials) == 0) or (serial is not None and serial not in serials): 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) time.sleep(0.1)
if timeout is not None and (time.monotonic() - t_start) > timeout: if timeout is not None and (time.monotonic() - t_start) > timeout:
return False return False
@@ -806,10 +802,10 @@ class Panda:
tx = tx[bs:] tx = tx[bs:]
if len(tx) == 0: if len(tx) == 0:
break break
logging.error("CAN: PARTIAL SEND MANY, RETRYING") logger.error("CAN: PARTIAL SEND MANY, RETRYING")
break break
except (usb1.USBErrorIO, usb1.USBErrorOverflow): 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): def can_send(self, addr, dat, bus, timeout=CAN_SEND_TIMEOUT_MS):
self.can_send_many([[addr, dat, bus]], timeout=timeout) self.can_send_many([[addr, dat, bus]], timeout=timeout)
@@ -822,7 +818,7 @@ class Panda:
dat = self._handle.bulkRead(1, 16384) # Max receive batch size + 2 extra reserve frames dat = self._handle.bulkRead(1, 16384) # Max receive batch size + 2 extra reserve frames
break break
except (usb1.USBErrorIO, usb1.USBErrorOverflow): except (usb1.USBErrorIO, usb1.USBErrorOverflow):
logging.error("CAN: BAD RECV, RETRYING") logger.error("CAN: BAD RECV, RETRYING")
time.sleep(0.1) time.sleep(0.1)
msgs, self.can_rx_overflow_buffer = unpack_can_buffer(self.can_rx_overflow_buffer + dat) msgs, self.can_rx_overflow_buffer = unpack_can_buffer(self.can_rx_overflow_buffer + dat)
return msgs return msgs

View File

@@ -5,7 +5,6 @@ import fcntl
import math import math
import time import time
import struct import struct
import logging
import threading import threading
from contextlib import contextmanager from contextlib import contextmanager
from functools import reduce from functools import reduce
@@ -13,6 +12,7 @@ from collections.abc import Callable
from .base import BaseHandle, BaseSTBootloaderHandle, TIMEOUT from .base import BaseHandle, BaseSTBootloaderHandle, TIMEOUT
from .constants import McuType, MCU_TYPE_BY_IDCODE, USBPACKET_MAX_SIZE from .constants import McuType, MCU_TYPE_BY_IDCODE, USBPACKET_MAX_SIZE
from .utils import logger
try: try:
import spidev import spidev
@@ -167,23 +167,23 @@ class PandaSpiHandle(BaseHandle):
def _transfer_spidev(self, spi, endpoint: int, data, timeout: int, max_rx_len: int = 1000, expect_disconnect: bool = False) -> bytes: 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) 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 = struct.pack("<BBHH", SYNC, endpoint, len(data), max_rx_len)
packet += bytes([self._calc_checksum(packet), ]) packet += bytes([self._calc_checksum(packet), ])
spi.xfer2(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) 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)]) packet = bytes([*data, self._calc_checksum(data)])
spi.xfer2(packet) spi.xfer2(packet)
if expect_disconnect: if expect_disconnect:
logging.debug("- expecting disconnect, returning") logger.debug("- expecting disconnect, returning")
return b"" return b""
else: else:
logging.debug("- waiting for data ACK") logger.debug("- waiting for data ACK")
preread_len = USBPACKET_MAX_SIZE + 1 # read enough for a controlRead preread_len = USBPACKET_MAX_SIZE + 1 # read enough for a controlRead
dat = self._wait_for_ack(spi, DACK, timeout, 0x13, length=3 + preread_len) dat = self._wait_for_ack(spi, DACK, timeout, 0x13, length=3 + preread_len)
@@ -222,21 +222,21 @@ class PandaSpiHandle(BaseHandle):
return bytes(self.rx_buf[:ret]) return bytes(self.rx_buf[:ret])
def _transfer(self, endpoint: int, data, timeout: int, max_rx_len: int = 1000, expect_disconnect: bool = False) -> bytes: 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) logger.debug("starting transfer: endpoint=%d, max_rx_len=%d", endpoint, max_rx_len)
logging.debug("==============================================") logger.debug("==============================================")
n = 0 n = 0
start_time = time.monotonic() start_time = time.monotonic()
exc = PandaSpiException() exc = PandaSpiException()
while (timeout == 0) or (time.monotonic() - start_time) < timeout*1e-3: while (timeout == 0) or (time.monotonic() - start_time) < timeout*1e-3:
n += 1 n += 1
logging.debug("\ntry #%d", n) logger.debug("\ntry #%d", n)
with self.dev.acquire() as spi: with self.dev.acquire() as spi:
try: try:
return self._transfer_raw(spi, endpoint, data, timeout, max_rx_len, expect_disconnect) return self._transfer_raw(spi, endpoint, data, timeout, max_rx_len, expect_disconnect)
except PandaSpiException as e: except PandaSpiException as e:
exc = e exc = e
logging.debug("SPI transfer failed, retrying", exc_info=True) logger.debug("SPI transfer failed, retrying", exc_info=True)
raise exc raise exc
@@ -245,7 +245,7 @@ class PandaSpiHandle(BaseHandle):
def _get_version(spi) -> bytes: def _get_version(spi) -> bytes:
spi.writebytes(vers_str) spi.writebytes(vers_str)
logging.debug("- waiting for echo") logger.debug("- waiting for echo")
start = time.monotonic() start = time.monotonic()
while True: while True:
version_bytes = spi.readbytes(len(vers_str) + 2) version_bytes = spi.readbytes(len(vers_str) + 2)
@@ -273,7 +273,7 @@ class PandaSpiHandle(BaseHandle):
return _get_version(spi) return _get_version(spi)
except PandaSpiException as e: except PandaSpiException as e:
exc = 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 raise exc
# libusb1 functions # libusb1 functions
@@ -378,7 +378,7 @@ class STBootloaderSPIHandle(BaseSTBootloaderHandle):
return self._cmd_no_retry(cmd, data, read_bytes, predata) return self._cmd_no_retry(cmd, data, read_bytes, predata)
except PandaSpiException as e: except PandaSpiException as e:
exc = 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 raise exc
def _checksum(self, data: bytes) -> bytes: def _checksum(self, data: bytes) -> bytes:

11
python/utils.py Normal file
View File

@@ -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)