Central logging. (pymodbus-dev#1324)

Author: janiversen

pymodbus/__init__.py

@@ -3,29 +3,20 @@
 Released under the the BSD license
 """
 
-import logging as __logging
-from logging import NullHandler as __null
+from logging import WARNING
 
 import pymodbus.version as __version
+from pymodbus.logging import Log
 
 
 __version__ = __version.version.short()
 __author__ = "Galen Collins"
 __maintainer__ = "dhoomakethu, janiversen"
 
-# ---------------------------------------------------------------------------#
-#  Block unhandled logging
-# ---------------------------------------------------------------------------#
-__logging.getLogger(__name__).addHandler(__null())
 
-
-def pymodbus_apply_logging_config(level=__logging.WARNING):
+def pymodbus_apply_logging_config(level=WARNING):
     """Apply basic logging configuration used by default by Pymodbus maintainers.
 
     Please call this function to format logging appropriately when opening issues.
     """
-    __logging.basicConfig(
-        format="%(asctime)s %(levelname)-5s %(module)s:%(lineno)s %(message)s",
-        datefmt="%H:%M:%S",
-        level=level,
-    )
+    Log.apply_logging_config(level)

pymodbus/client/base.py

@@ -2,7 +2,6 @@
 from __future__ import annotations
 
 import asyncio
-import logging
 import socket
 from dataclasses import dataclass
 
@@ -11,12 +10,10 @@
 from pymodbus.exceptions import ConnectionException, NotImplementedException
 from pymodbus.factory import ClientDecoder
 from pymodbus.framer import ModbusFramer
+from pymodbus.logging import Log
 from pymodbus.pdu import ModbusRequest, ModbusResponse
 from pymodbus.transaction import DictTransactionManager
-from pymodbus.utilities import ModbusTransactionState, hexlify_packets
-
-
-_logger = logging.getLogger(__name__)
+from pymodbus.utilities import ModbusTransactionState
 
 
 class ModbusBaseClient(ModbusClientMixin):
@@ -207,7 +204,7 @@ def send(self, request):
         :meta private:
         """
         if self.state != ModbusTransactionState.RETRYING:
-            _logger.debug('New Transaction state "SENDING"')
+            Log.debug('New Transaction state "SENDING"')
             self.state = ModbusTransactionState.SENDING
         return request
 
@@ -360,13 +357,12 @@ def raise_future(self, my_future, exc):
 
     def _connection_made(self):
         """Call upon a successful client connection."""
-        _logger.debug("Client connected to modbus server")
+        Log.debug("Client connected to modbus server")
         self._connected = True
 
     def _connection_lost(self, reason):
         """Call upon a client disconnect."""
-        txt = f"Client disconnected from modbus server: {reason}"
-        _logger.debug(txt)
+        Log.debug("Client disconnected from modbus server: {}", reason)
         self._connected = False
         for tid in list(self.transaction):
             self.raise_future(
@@ -389,17 +385,13 @@ def _execute(self, request, **kwargs):  # pylint: disable=unused-argument
         """Start the producer to send the next request to consumer.write(Frame(request))."""
         request.transaction_id = self.transaction.getNextTID()
         packet = self.framer.buildPacket(request)
-        if _logger.isEnabledFor(logging.DEBUG):
-            txt = f"send: {hexlify_packets(packet)}"
-            _logger.debug(txt)
+        Log.debug("send: {}", packet, ":hex")
         self.write_transport(packet)
         return self._build_response(request.transaction_id)
 
     def _data_received(self, data):
         """Get response, check for valid message, decode result."""
-        if _logger.isEnabledFor(logging.DEBUG):
-            txt = f"recv: {hexlify_packets(data)}"
-            _logger.debug(txt)
+        Log.debug("recv: {}", data, ":hex")
         self.framer.processIncomingPacket(data, self._handle_response, unit=0)
 
     def _handle_response(self, reply, **kwargs):  # pylint: disable=unused-argument
@@ -409,8 +401,7 @@ def _handle_response(self, reply, **kwargs):  # pylint: disable=unused-argument
             if handler := self.transaction.getTransaction(tid):
                 self.resolve_future(handler, reply)
             else:
-                txt = f"Unrequested message: {str(reply)}"
-                _logger.debug(txt)
+                Log.debug("Unrequested message: {}", reply, ":str")
 
     def _build_response(self, tid):
         """Return a deferred response for the current request."""

pymodbus/client/mixin.py

@@ -1,5 +1,4 @@
 """Modbus Client Common."""
-import logging
 from typing import List, Tuple, Union
 
 import pymodbus.bit_read_message as pdu_bit_read
@@ -13,9 +12,6 @@
 from pymodbus.pdu import ModbusRequest, ModbusResponse
 
 
-_logger = logging.getLogger(__name__)
-
-
 class ModbusClientMixin:  # pylint: disable=too-many-public-methods
     """**ModbusClientMixin**.
 

pymodbus/client/serial.py

@@ -1,6 +1,5 @@
 """Modbus client async serial communication."""
 import asyncio
-import logging
 import time
 from functools import partial
 
@@ -10,7 +9,8 @@
 from pymodbus.exceptions import ConnectionException
 from pymodbus.framer import ModbusFramer
 from pymodbus.framer.rtu_framer import ModbusRtuFramer
-from pymodbus.utilities import ModbusTransactionState, hexlify_packets
+from pymodbus.logging import Log
+from pymodbus.utilities import ModbusTransactionState
 
 
 try:
@@ -19,9 +19,6 @@
     pass
 
 
-_logger = logging.getLogger(__name__)
-
-
 class AsyncModbusSerialClient(ModbusBaseClient):
     """**AsyncModbusSerialClient**.
 
@@ -104,7 +101,7 @@ async def connect(self):  # pylint: disable=invalid-overridden-method
         # get current loop, if there are no loop a RuntimeError will be raised
         self.loop = asyncio.get_running_loop()
 
-        _logger.debug("Starting serial connection")
+        Log.debug("Starting serial connection")
         try:
             await create_serial_connection(
                 self.loop,
@@ -118,28 +115,26 @@ async def connect(self):  # pylint: disable=invalid-overridden-method
                 **self.params.kwargs,
             )
             await self._connected_event.wait()
-            txt = f"Connected to {self.params.port}"
-            _logger.info(txt)
+            Log.info("Connected to {}", self.params.port)
         except Exception as exc:  # pylint: disable=broad-except
-            txt = f"Failed to connect: {exc}"
-            _logger.warning(txt)
+            Log.warning("Failed to connect: {}", exc)
         return self.connected
 
     def protocol_made_connection(self, protocol):
         """Notify successful connection."""
-        _logger.info("Serial connected.")
+        Log.info("Serial connected.")
         if not self.connected:
             self._connected_event.set()
             self.protocol = protocol
         else:
-            _logger.error("Factory protocol connect callback called while connected.")
+            Log.error("Factory protocol connect callback called while connected.")
 
     def protocol_lost_connection(self, protocol):
         """Notify lost connection."""
         if self.connected:
-            _logger.info("Serial lost connection.")
+            Log.info("Serial lost connection.")
             if protocol is not self.protocol:
-                _logger.error("Serial: protocol is not self.protocol.")
+                Log.error("Serial: protocol is not self.protocol.")
 
             self._connected_event.clear()
             if self.protocol is not None:
@@ -148,7 +143,7 @@ def protocol_lost_connection(self, protocol):
             # if self.host:
             #     asyncio.asynchronous(self._reconnect())
         else:
-            _logger.error("Serial, lost_connection but not connected.")
+            Log.error("Serial, lost_connection but not connected.")
 
 
 class ModbusSerialClient(ModbusBaseClient):
@@ -235,7 +230,7 @@ def connect(self):
                     self.socket.interCharTimeout = self.inter_char_timeout
                 self.last_frame_end = None
         except serial.SerialException as msg:
-            _logger.error(msg)
+            Log.error("{}", msg)
             self.close()
         return self.socket is not None
 
@@ -270,16 +265,15 @@ def send(self, request):
                 if waitingbytes := self._in_waiting():
                     result = self.socket.read(waitingbytes)
                     if self.state == ModbusTransactionState.RETRYING:
-                        txt = f"Sending available data in recv buffer {hexlify_packets(result)}"
-                        _logger.debug(txt)
+                        Log.debug(
+                            "Sending available data in recv buffer {}", result, ":hex"
+                        )
                         return result
-                    if _logger.isEnabledFor(logging.WARNING):
-                        txt = f"Cleanup recv buffer before send: {hexlify_packets(result)}"
-                        _logger.warning(txt)
+                    Log.warning("Cleanup recv buffer before send: {}", result, ":hex")
             except NotImplementedError:
                 pass
             if self.state != ModbusTransactionState.SENDING:
-                _logger.debug('New Transaction state "SENDING"')
+                Log.debug('New Transaction state "SENDING"')
                 self.state = ModbusTransactionState.SENDING
             size = self.socket.write(request)
             return size

pymodbus/client/sync_diag.py

@@ -1,16 +1,14 @@
 """Sync diag."""
-import logging
 import socket
 import time
 
 from pymodbus.client.tcp import ModbusTcpClient
 from pymodbus.constants import Defaults
 from pymodbus.exceptions import ConnectionException
 from pymodbus.framer.socket_framer import ModbusSocketFramer
+from pymodbus.logging import Log
 
 
-_logger = logging.getLogger(__name__)
-
 LOG_MSGS = {
     "conn_msg": "Connecting to modbus device %s",
     "connfail_msg": "Connection to (%s, %s) failed: %s",
@@ -91,23 +89,21 @@ def connect(self):
         if self.socket:
             return True
         try:
-            _logger.info(LOG_MSGS["conn_msg"], self)
+            Log.info(LOG_MSGS["conn_msg"], self)
             self.socket = socket.create_connection(
                 (self.params.host, self.params.port),
                 timeout=self.params.timeout,
                 source_address=self.params.source_address,
             )
         except socket.error as msg:
-            _logger.error(
-                LOG_MSGS["connfail_msg"], self.params.host, self.params.port, msg
-            )
+            Log.error(LOG_MSGS["connfail_msg"], self.params.host, self.params.port, msg)
             self.close()
         return self.socket is not None
 
     def close(self):
         """Close the underlying socket connection."""
         if self.socket:
-            _logger.info(LOG_MSGS["discon_msg"], self)
+            Log.info(LOG_MSGS["discon_msg"], self)
             self.socket.close()
         self.socket = None
 
@@ -122,29 +118,29 @@ def recv(self, size):
             if self.warn_delay_limit is not None and delay >= self.warn_delay_limit:
                 self._log_delayed_response(len(result), size, delay)
             elif not size:
-                _logger.debug(LOG_MSGS["timelimit_read_msg"], delay, len(result))
+                Log.debug(LOG_MSGS["timelimit_read_msg"], delay, len(result))
             else:
-                _logger.debug(LOG_MSGS["read_msg"], delay, len(result), size)
+                Log.debug(LOG_MSGS["read_msg"], delay, len(result), size)
 
             return result
         except ConnectionException as exc:
             # Only log actual network errors, "if not self.socket" then it's a internal code issue
             if "Connection unexpectedly closed" in exc.string:
-                _logger.error(LOG_MSGS["unexpected_dc_msg"], self, exc)
+                Log.error(LOG_MSGS["unexpected_dc_msg"], self, exc)
             raise ConnectionException from exc
 
     def _log_delayed_response(self, result_len, size, delay):
         """Log delayed response."""
         if not size and result_len > 0:
-            _logger.info(LOG_MSGS["timelimit_read_msg"], delay, result_len)
+            Log.info(LOG_MSGS["timelimit_read_msg"], delay, result_len)
         elif (
             (not result_len) or (size and result_len < size)
         ) and delay >= self.params.timeout:
             size_txt = size if size else "in timelimit read"
             read_type = f"of {size_txt} expected"
-            _logger.warning(LOG_MSGS["timeout_msg"], delay, result_len, read_type)
+            Log.warning(LOG_MSGS["timeout_msg"], delay, result_len, read_type)
         else:
-            _logger.warning(LOG_MSGS["delay_msg"], delay, result_len, size)
+            Log.warning(LOG_MSGS["delay_msg"], delay, result_len, size)
 
     def __str__(self):
         """Build a string representation of the connection.
@@ -163,9 +159,7 @@ def get_client():
 
     :returns: ModbusTcpClient or a child class thereof
     """
-    return (
-        ModbusTcpDiagClient if _logger.isEnabledFor(logging.ERROR) else ModbusTcpClient
-    )
+    return ModbusTcpDiagClient
 
 
 # --------------------------------------------------------------------------- #