separate car logger forwarded to cloudlog (#33170)

* car logger

* try this

* fix double printing!

* clean up

* need to import where we actually use it (card won't be in submodule)

* NullHandler does not forward everything properly, need propagate=False to stop root logger from printing

* card is staying

* set up

* forward
old-commit-hash: 12a7b7f7fb

.importlinter

@@ -18,6 +18,7 @@ forbidden_modules =
     openpilot.teleoprtc
     openpilot.tinygrad
 ignore_imports =
+    # remove these
     openpilot.selfdrive.car.card -> openpilot.common.realtime
     openpilot.selfdrive.car.card -> openpilot.selfdrive.controls.lib.events
     openpilot.selfdrive.car.interfaces -> openpilot.selfdrive.controls.lib.events
@@ -26,16 +27,13 @@ ignore_imports =
     openpilot.selfdrive.car.tests.test_models -> openpilot.tools.lib.route
     openpilot.selfdrive.car.tests.test_models -> openpilot.system.hardware.hw
     openpilot.selfdrive.car.tests.test_models -> openpilot.selfdrive.test.helpers
-    openpilot.selfdrive.car.isotp_parallel_query -> openpilot.common.swaglog
-    openpilot.selfdrive.car.fw_versions -> openpilot.common.swaglog
-    openpilot.selfdrive.car.disable_ecu -> openpilot.common.swaglog
-    openpilot.selfdrive.car.vin -> openpilot.common.swaglog
-    openpilot.selfdrive.car.ecu_addrs -> openpilot.common.swaglog
-    openpilot.selfdrive.car.car_helpers -> openpilot.common.swaglog
     openpilot.selfdrive.car.car_helpers -> openpilot.system.version
     openpilot.selfdrive.car.interfaces -> openpilot.selfdrive.controls.lib.drive_helpers
     openpilot.selfdrive.car.tests.test_car_interfaces -> openpilot.selfdrive.controls.lib.latcontrol_angle
     openpilot.selfdrive.car.tests.test_car_interfaces -> openpilot.selfdrive.controls.lib.longcontrol
     openpilot.selfdrive.car.tests.test_car_interfaces -> openpilot.selfdrive.controls.lib.latcontrol_torque
     openpilot.selfdrive.car.tests.test_car_interfaces -> openpilot.selfdrive.controls.lib.latcontrol_pid
+
+    # these are okay
+    openpilot.selfdrive.car.card -> openpilot.common.swaglog
 unmatched_ignore_imports_alerting = warn

common/swaglog.py

@@ -104,6 +104,15 @@ class UnixDomainSocketHandler(logging.Handler):
       pass
 
 
+class ForwardingHandler(logging.Handler):
+  def __init__(self, target_logger):
+    super().__init__()
+    self.target_logger = target_logger
+
+  def emit(self, record):
+    self.target_logger.handle(record)
+
+
 def add_file_handler(log):
   """
   Function to add the file log handler to swaglog.

selfdrive/car/__init__.py

@@ -1,4 +1,5 @@
 # functions common among cars
+import logging
 from collections import namedtuple
 from dataclasses import dataclass
 from enum import IntFlag, ReprEnum, EnumType
@@ -12,6 +13,11 @@ from openpilot.common.numpy_fast import clip, interp
 from openpilot.common.utils import Freezable
 from openpilot.selfdrive.car.docs_definitions import CarDocs
 
+# set up logging
+carlog = logging.getLogger('carlog')
+carlog.setLevel(logging.INFO)
+carlog.propagate = False
+
 DT_CTRL = 0.01  # car state and control loop timestep (s)
 
 # kg of standard extra cargo to count for drive, gas, etc...

selfdrive/car/car_helpers.py

@@ -4,12 +4,12 @@ from collections.abc import Callable
 
 from cereal import car
 from openpilot.common.params import Params
+from openpilot.selfdrive.car import carlog
 from openpilot.selfdrive.car.interfaces import get_interface_attr
 from openpilot.selfdrive.car.fingerprints import eliminate_incompatible_cars, all_legacy_fingerprint_cars
 from openpilot.selfdrive.car.vin import get_vin, is_valid_vin, VIN_UNKNOWN
 from openpilot.selfdrive.car.fw_versions import get_fw_versions_ordered, get_present_ecus, match_fw_to_car, set_obd_multiplexing
 from openpilot.selfdrive.car.mock.values import CAR as MOCK
-from openpilot.common.swaglog import cloudlog
 import cereal.messaging as messaging
 from openpilot.selfdrive.car import gen_empty_fingerprint
 from openpilot.system.version import get_build_metadata
@@ -127,12 +127,12 @@ def fingerprint(logcan, sendcan, num_pandas):
 
     if cached_params is not None and len(cached_params.carFw) > 0 and \
        cached_params.carVin is not VIN_UNKNOWN and not disable_fw_cache:
-      cloudlog.warning("Using cached CarParams")
+      carlog.warning("Using cached CarParams")
       vin_rx_addr, vin_rx_bus, vin = -1, -1, cached_params.carVin
       car_fw = list(cached_params.carFw)
       cached = True
     else:
-      cloudlog.warning("Getting VIN & FW versions")
+      carlog.warning("Getting VIN & FW versions")
       # enable OBD multiplexing for VIN query
       # NOTE: this takes ~0.1s and is relied on to allow sendcan subscriber to connect in time
       set_obd_multiplexing(params, True)
@@ -149,9 +149,9 @@ def fingerprint(logcan, sendcan, num_pandas):
     cached = False
 
   if not is_valid_vin(vin):
-    cloudlog.event("Malformed VIN", vin=vin, error=True)
+    carlog.error({"event": "Malformed VIN", "vin": vin})
     vin = VIN_UNKNOWN
-  cloudlog.warning("VIN %s", vin)
+  carlog.warning("VIN %s", vin)
   params.put("CarVin", vin)
 
   # disable OBD multiplexing for CAN fingerprinting and potential ECU knockouts
@@ -178,9 +178,9 @@ def fingerprint(logcan, sendcan, num_pandas):
     car_fingerprint = fixed_fingerprint
     source = car.CarParams.FingerprintSource.fixed
 
-  cloudlog.event("fingerprinted", car_fingerprint=car_fingerprint, source=source, fuzzy=not exact_match, cached=cached,
+  carlog.error({"event": "fingerprinted", "car_fingerprint": car_fingerprint, "source": source, "fuzzy": not exact_match,
-                 fw_count=len(car_fw), ecu_responses=list(ecu_rx_addrs), vin_rx_addr=vin_rx_addr, vin_rx_bus=vin_rx_bus,
+                 "cached": cached, "fw_count": len(car_fw), "ecu_responses": list(ecu_rx_addrs), "vin_rx_addr": vin_rx_addr,
-                 fingerprints=repr(finger), fw_query_time=fw_query_time, error=True)
+                 "vin_rx_bus": vin_rx_bus, "fingerprints": repr(finger), "fw_query_time": fw_query_time})
 
   return car_fingerprint, finger, vin, car_fw, source, exact_match
 
@@ -194,7 +194,7 @@ def get_car(logcan, sendcan, experimental_long_allowed, num_pandas=1):
   candidate, fingerprints, vin, car_fw, source, exact_match = fingerprint(logcan, sendcan, num_pandas)
 
   if candidate is None:
-    cloudlog.event("car doesn't match any fingerprints", fingerprints=repr(fingerprints), error=True)
+    carlog.error({"event": "car doesn't match any fingerprints", "fingerprints": repr(fingerprints)})
     candidate = "MOCK"
 
   CarInterface, _, _ = interfaces[candidate]

selfdrive/car/card.py

@@ -10,9 +10,10 @@ from panda import ALTERNATIVE_EXPERIENCE
 
 from openpilot.common.params import Params
 from openpilot.common.realtime import config_realtime_process, Priority, Ratekeeper
+from openpilot.common.swaglog import cloudlog, ForwardingHandler
 
 from openpilot.selfdrive.pandad import can_list_to_can_capnp
-from openpilot.selfdrive.car import DT_CTRL
+from openpilot.selfdrive.car import DT_CTRL, carlog
 from openpilot.selfdrive.car.car_helpers import get_car, get_one_can
 from openpilot.selfdrive.car.interfaces import CarInterfaceBase
 from openpilot.selfdrive.controls.lib.events import Events
@@ -21,6 +22,9 @@ REPLAY = "REPLAY" in os.environ
 
 EventName = car.CarEvent.EventName
 
+# forward
+carlog.addHandler(ForwardingHandler(cloudlog))
+
 
 class Car:
   CI: CarInterfaceBase

selfdrive/car/disable_ecu.py

@@ -1,6 +1,6 @@
 #!/usr/bin/env python3
+from openpilot.selfdrive.car import carlog
 from openpilot.selfdrive.car.isotp_parallel_query import IsoTpParallelQuery
-from openpilot.common.swaglog import cloudlog
 
 EXT_DIAG_REQUEST = b'\x10\x03'
 EXT_DIAG_RESPONSE = b'\x50\x03'
@@ -14,26 +14,26 @@ def disable_ecu(logcan, sendcan, bus=0, addr=0x7d0, sub_addr=None, com_cont_req=
 
   This is used to disable the radar in some cars. Openpilot will emulate the radar.
   WARNING: THIS DISABLES AEB!"""
-  cloudlog.warning(f"ecu disable {hex(addr), sub_addr} ...")
+  carlog.warning(f"ecu disable {hex(addr), sub_addr} ...")
 
   for i in range(retry):
     try:
       query = IsoTpParallelQuery(sendcan, logcan, bus, [(addr, sub_addr)], [EXT_DIAG_REQUEST], [EXT_DIAG_RESPONSE], debug=debug)
 
       for _, _ in query.get_data(timeout).items():
-        cloudlog.warning("communication control disable tx/rx ...")
+        carlog.warning("communication control disable tx/rx ...")
 
         query = IsoTpParallelQuery(sendcan, logcan, bus, [(addr, sub_addr)], [com_cont_req], [COM_CONT_RESPONSE], debug=debug)
         query.get_data(0)
 
-        cloudlog.warning("ecu disabled")
+        carlog.warning("ecu disabled")
         return True
 
     except Exception:
-      cloudlog.exception("ecu disable exception")
+      carlog.exception("ecu disable exception")
 
-    cloudlog.error(f"ecu disable retry ({i + 1}) ...")
+    carlog.error(f"ecu disable retry ({i + 1}) ...")
-  cloudlog.error("ecu disable failed")
+  carlog.error("ecu disable failed")
   return False
 
 

selfdrive/car/ecu_addrs.py

@@ -4,10 +4,9 @@ import time
 
 import cereal.messaging as messaging
 from panda.python.uds import SERVICE_TYPE
-from openpilot.selfdrive.car import make_tester_present_msg
+from openpilot.selfdrive.car import make_tester_present_msg, carlog
 from openpilot.selfdrive.car.fw_query_definitions import EcuAddrBusType
 from openpilot.selfdrive.pandad import can_list_to_can_capnp
-from openpilot.common.swaglog import cloudlog
 
 
 def _is_tester_present_response(msg: capnp.lib.capnp._DynamicStructReader, subaddr: int = None) -> bool:
@@ -45,7 +44,7 @@ def get_ecu_addrs(logcan: messaging.SubSocket, sendcan: messaging.PubSocket, que
       for packet in can_packets:
         for msg in packet.can:
           if not len(msg.dat):
-            cloudlog.warning("ECU addr scan: skipping empty remote frame")
+            carlog.warning("ECU addr scan: skipping empty remote frame")
             continue
 
           subaddr = None if (msg.address, None, msg.src) in responses else msg.dat[0]
@@ -56,7 +55,7 @@ def get_ecu_addrs(logcan: messaging.SubSocket, sendcan: messaging.PubSocket, que
                 print(f"Duplicate ECU address: {hex(msg.address)}")
             ecu_responses.add((msg.address, subaddr, msg.src))
   except Exception:
-    cloudlog.exception("ECU addr scan exception")
+    carlog.exception("ECU addr scan exception")
   return ecu_responses
 
 

selfdrive/car/fw_versions.py

@@ -9,7 +9,7 @@ import capnp
 import panda.python.uds as uds
 from cereal import car
 from openpilot.common.params import Params
-from openpilot.common.swaglog import cloudlog
+from openpilot.selfdrive.car import carlog
 from openpilot.selfdrive.car.ecu_addrs import get_ecu_addrs
 from openpilot.selfdrive.car.fingerprints import FW_VERSIONS
 from openpilot.selfdrive.car.fw_query_definitions import AddrType, EcuAddrBusType, FwQueryConfig, LiveFwVersions, OfflineFwVersions
@@ -97,7 +97,7 @@ def match_fw_to_car_fuzzy(live_fw_versions: LiveFwVersions, match_brand: str = N
   # if there are enough matches. FIXME: parameterize this or require all ECUs to exist like exact matching
   if match and len(matched_ecus) >= 2:
     if log:
-      cloudlog.error(f"Fingerprinted {match} using fuzzy match. {len(matched_ecus)} matching ECUs")
+      carlog.error(f"Fingerprinted {match} using fuzzy match. {len(matched_ecus)} matching ECUs")
     return {match}
   else:
     return set()
@@ -230,11 +230,11 @@ def get_brand_ecu_matches(ecu_rx_addrs: set[EcuAddrBusType]) -> dict[str, set[Ad
 
 def set_obd_multiplexing(params: Params, obd_multiplexing: bool):
   if params.get_bool("ObdMultiplexingEnabled") != obd_multiplexing:
-    cloudlog.warning(f"Setting OBD multiplexing to {obd_multiplexing}")
+    carlog.warning(f"Setting OBD multiplexing to {obd_multiplexing}")
     params.remove("ObdMultiplexingChanged")
     params.put_bool("ObdMultiplexingEnabled", obd_multiplexing)
     params.get_bool("ObdMultiplexingChanged", block=True)
-    cloudlog.warning("OBD multiplexing set successfully")
+    carlog.warning("OBD multiplexing set successfully")
 
 
 def get_fw_versions_ordered(logcan, sendcan, vin: str, ecu_rx_addrs: set[EcuAddrBusType], timeout: float = 0.1, num_pandas: int = 1,
@@ -331,7 +331,7 @@ def get_fw_versions(logcan, sendcan, query_brand: str = None, extra: OfflineFwVe
 
               car_fw.append(f)
         except Exception:
-          cloudlog.exception("FW query exception")
+          carlog.exception("FW query exception")
 
   return car_fw
 

selfdrive/car/isotp_parallel_query.py

@@ -3,9 +3,9 @@ from collections import defaultdict
 from functools import partial
 
 import cereal.messaging as messaging
-from openpilot.common.swaglog import cloudlog
+from openpilot.selfdrive.car import carlog
-from openpilot.selfdrive.pandad import can_list_to_can_capnp
 from openpilot.selfdrive.car.fw_query_definitions import AddrType
+from openpilot.selfdrive.pandad import can_list_to_can_capnp
 from panda.python.uds import CanClient, IsoTpMessage, FUNCTIONAL_ADDRS, get_rx_addr_for_tx_addr
 
 
@@ -109,7 +109,7 @@ class IsoTpParallelQuery:
         try:
           dat, rx_in_progress = msg.recv()
         except Exception:
-          cloudlog.exception(f"Error processing UDS response: {tx_addr}")
+          carlog.exception(f"Error processing UDS response: {tx_addr}")
           request_done[tx_addr] = True
           continue
 
@@ -123,7 +123,7 @@ class IsoTpParallelQuery:
 
         # Log unexpected empty responses
         if len(dat) == 0:
-          cloudlog.error(f"iso-tp query empty response: {tx_addr}")
+          carlog.error(f"iso-tp query empty response: {tx_addr}")
           request_done[tx_addr] = True
           continue
 
@@ -143,10 +143,10 @@ class IsoTpParallelQuery:
           error_code = dat[2] if len(dat) > 2 else -1
           if error_code == 0x78:
             response_timeouts[tx_addr] = time.monotonic() + self.response_pending_timeout
-            cloudlog.error(f"iso-tp query response pending: {tx_addr}")
+            carlog.error(f"iso-tp query response pending: {tx_addr}")
           else:
             request_done[tx_addr] = True
-            cloudlog.error(f"iso-tp query bad response: {tx_addr} - 0x{dat.hex()}")
+            carlog.error(f"iso-tp query bad response: {tx_addr} - 0x{dat.hex()}")
 
       # Mark request done if address timed out
       cur_time = time.monotonic()
@@ -154,12 +154,12 @@ class IsoTpParallelQuery:
         if cur_time - response_timeouts[tx_addr] > 0:
           if not request_done[tx_addr]:
             if request_counter[tx_addr] > 0:
-              cloudlog.error(f"iso-tp query timeout after receiving partial response: {tx_addr}")
+              carlog.error(f"iso-tp query timeout after receiving partial response: {tx_addr}")
             elif tx_addr in addrs_responded:
-              cloudlog.error(f"iso-tp query timeout while receiving response: {tx_addr}")
+              carlog.error(f"iso-tp query timeout while receiving response: {tx_addr}")
             # TODO: handle functional addresses
             # else:
-            #   cloudlog.error(f"iso-tp query timeout with no response: {tx_addr}")
+            #   carlog.error(f"iso-tp query timeout with no response: {tx_addr}")
           request_done[tx_addr] = True
 
       # Break if all requests are done (finished or timed out)
@@ -167,7 +167,7 @@ class IsoTpParallelQuery:
         break
 
       if cur_time - start_time > total_timeout:
-        cloudlog.error("iso-tp query timeout while receiving data")
+        carlog.error("iso-tp query timeout while receiving data")
         break
 
     return results

selfdrive/car/tests/test_fw_fingerprint.py

@@ -322,11 +322,11 @@ class TestFwFingerprintTiming:
     # TODO: replace this with full fingerprint simulation testing
     # https://github.com/commaai/panda/pull/1329
 
-    def fake_cloudlog_exception(*args, **kwargs):
+    def fake_carlog_exception(*args, **kwargs):
       raise
 
     mocker.patch("openpilot.selfdrive.car.fw_versions.set_obd_multiplexing", lambda *args: None)
-    mocker.patch("openpilot.common.swaglog.cloudlog.exception", fake_cloudlog_exception)
+    mocker.patch("openpilot.selfdrive.car.carlog.exception", fake_carlog_exception)
     fake_socket = FakeSocket()
     for brand in FW_QUERY_CONFIGS.keys():
       with subtests.test(brand=brand):

selfdrive/car/vin.py

@@ -3,9 +3,9 @@ import re
 
 import cereal.messaging as messaging
 from panda.python.uds import get_rx_addr_for_tx_addr, FUNCTIONAL_ADDRS
+from openpilot.selfdrive.car import carlog
 from openpilot.selfdrive.car.isotp_parallel_query import IsoTpParallelQuery
 from openpilot.selfdrive.car.fw_query_definitions import STANDARD_VIN_ADDRS, StdQueries
-from openpilot.common.swaglog import cloudlog
 
 VIN_UNKNOWN = "0" * 17
 VIN_RE = "[A-HJ-NPR-Z0-9]{17}"
@@ -50,12 +50,12 @@ def get_vin(logcan, sendcan, buses, timeout=0.1, retry=2, debug=False):
               if vin.startswith(b'\x11'):
                 vin = vin[1:18]
 
-              cloudlog.error(f"got vin with {request=}")
+              carlog.error(f"got vin with {request=}")
               return get_rx_addr_for_tx_addr(addr, rx_offset=rx_offset), bus, vin.decode()
         except Exception:
-          cloudlog.exception("VIN query exception")
+          carlog.exception("VIN query exception")
 
-    cloudlog.error(f"vin query retry ({i+1}) ...")
+    carlog.error(f"vin query retry ({i+1}) ...")
 
   return -1, -1, VIN_UNKNOWN