From 37a33a558186e51b4b94603074b17e17ac3e1922 Mon Sep 17 00:00:00 2001
From: Aigars Mahinovs <Aigars.Mahinovs@bmw.de>
Date: Mon, 25 Sep 2023 16:40:34 +0200
Subject: [PATCH] Reduce reconnection message spam

When reading a DLT from a device that is offline for a while
(for example during flashing), DLT would spam 3 messages
every 5 seconds.

Reduce this to 1 message per minute and add time information
into the messages to increase their usefulness
---
 dlt/dlt.py                 | 14 +++++++++-----
 dlt/dlt_broker_handlers.py | 34 +++++++++++++++++++++++++++-------
 2 files changed, 36 insertions(+), 12 deletions(-)

diff --git a/dlt/dlt.py b/dlt/dlt.py
index 782944b..f9bd438 100644
--- a/dlt/dlt.py
+++ b/dlt/dlt.py
@@ -923,13 +923,15 @@ def connect(self, timeout=None):
         immediately
 
         :param int|None timeout: Seconds to wait for connection
+        :param bool|False silent: Do not log debug info
         :returns: True if connected successfully, False otherwise
         :rtype: bool
         """
         connected = None
         error_count = 0
         if not self.is_udp_multicast:
-            logger.info("Connecting DLTClient using TCP Connection")
+            if self.verbose:
+                logger.info("Connecting DLTClient using TCP Connection")
             if timeout:
                 end_time = time.time() + timeout
                 while time.time() < end_time:
@@ -939,7 +941,7 @@ def connect(self, timeout=None):
                             (ctypes.string_at(self.servIP), self.port), timeout=timeout_remaining
                         )
                     except IOError as exc:
-                        if error_count < MAX_LOG_IN_ROW:
+                        if error_count < MAX_LOG_IN_ROW and self.verbose:
                             logger.debug(
                                 "DLT client connect failed to connect to %s:%s : %s", self.servIP, self.port, exc
                             )
@@ -966,14 +968,16 @@ def connect(self, timeout=None):
                 # connection loss in the main_loop below as described at
                 # http://stefan.buettcher.org/cs/conn_closed.html
                 self._connected_socket = socket.fromfd(self.sock, socket.AF_INET6, socket.SOCK_STREAM)
-            if error_count > MAX_LOG_IN_ROW:
+            if error_count > MAX_LOG_IN_ROW and self.verbose:
                 logger.debug("Surpressed %d messages for failed connection attempts", error_count - MAX_LOG_IN_ROW)
 
         else:
-            logger.info("Connecting DLTClient using UDP Connection")
+            if self.verbose:
+                logger.info("Connecting DLTClient using UDP Connection")
             connected = dltlib.dlt_client_connect(ctypes.byref(self), self.verbose)
 
-        logger.info("DLT Connection return: %s", connected)
+        if self.verbose:
+            logger.info("DLT Connection return: %s", connected)
         return connected == DLT_RETURN_OK
 
     def disconnect(self):
diff --git a/dlt/dlt_broker_handlers.py b/dlt/dlt_broker_handlers.py
index e104065..babe3e3 100644
--- a/dlt/dlt_broker_handlers.py
+++ b/dlt/dlt_broker_handlers.py
@@ -400,6 +400,8 @@ def __init__(
         self.timeout = client_cfg.get("timeout", DLT_CLIENT_TIMEOUT)
         self._client = None
         self.tracefile = None
+        self.last_connected = time.time()
+        self.last_message = time.time() - 120.0
 
     def is_valid_message(self, message):
         return message and (message.apid != "" or message.ctid != "")
@@ -411,12 +413,13 @@ def _client_connect(self):
         :returns: True if connected, False otherwise
         :rtype: bool
         """
-        logger.debug(
-            "Creating DLTClient (ip_address='%s', Port='%s', logfile='%s')",
-            self._ip_address,
-            self._port,
-            self._filename,
-        )
+        if self.verbose:
+            logger.debug(
+                "Creating DLTClient (ip_address='%s', Port='%s', logfile='%s')",
+                self._ip_address,
+                self._port,
+                self._filename,
+            )
         self._client = DLTClient(servIP=self._ip_address, port=self._port, verbose=self.verbose)
         connected = self._client.connect(self.timeout)
         if connected:
@@ -434,11 +437,28 @@ def run(self):
             if not self._client_connect():
                 # keep trying to reconnect, until we either successfully
                 # connect or the stop_flag is set
+                if time.time() - self.last_message > 60:
+                    # Once per minute log that we still have no DLT Connection
+                    logger.info(
+                        "DLT connection to %s missing since %s seconds",
+                        self._ip_address,
+                        time.time() - self.last_connected,
+                    )
+                    self.last_message = time.time()
                 continue
             try:
+                if self.last_connected:
+                    logger.info(
+                        "DLT connection to %s re-established after %s seconds",
+                        self._ip_address,
+                        time() - self.last_connected,
+                    )
+                self.last_connected = time.time()
                 res = py_dlt_client_main_loop(self._client, verbose=0, callback=self.handle, dumpfile=self.tracefile)
                 if res is False and not self.mp_stop_flag.is_set():  # main loop returned False
-                    logger.error("DLT connection lost. Restarting DLT client")
+                    logger.warning("DLT connection to %s lost. Restarting DLT client", self._ip_address)
+                    self.last_connected = time.time()
+                    self.last_message = time.time()
                     exception_occured = True
             except KeyboardInterrupt:
                 exception_occured = True