improve logging output

CHANGELOG.md

@@ -7,6 +7,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+- improve logging: add protocol or node_id to connection logs
+- improve logging: log ignored AT+ or MODBUS commands
+- fix typo in docker-compose.yaml
 - trace heartbeat and regular modbus pakets witl log level DEBUG
 - GEN3PLUS: don't forward ack paket from tsun to the inverter
 - add allow and block filter for AT+ commands

app/src/async_stream.py

@@ -17,11 +17,12 @@ class AsyncStream():
 
     async def server_loop(self, addr):
         '''Loop for receiving messages from the inverter (server-side)'''
-        logging.info(f'Accept connection from  {addr}')
+        logging.info(f'[{self.node_id}] Accept connection from {addr}')
         self.inc_counter('Inverter_Cnt')
         await self.loop()
         self.dec_counter('Inverter_Cnt')
-        logging.info(f'Server loop stopped for r{self.r_addr}')
+        logging.info(f'[{self.node_id}] Server loop stopped for'
+                     f' r{self.r_addr}')
 
         # if the server connection closes, we also have to disconnect
         # the connection to te TSUN cloud
@@ -36,7 +37,8 @@ class AsyncStream():
     async def client_loop(self, addr):
         '''Loop for receiving messages from the TSUN cloud (client-side)'''
         clientStream = await self.remoteStream.loop()
-        logging.info(f'Client loop stopped for l{clientStream.l_addr}')
+        logging.info(f'[{self.node_id}] Client loop stopped for'
+                     f' l{clientStream.l_addr}')
 
         # if the client connection closes, we don't touch the server
         # connection. Instead we erase the client connection stream,
@@ -66,14 +68,14 @@ class AsyncStream():
                     await self.async_publ_mqtt()
 
             except OSError as error:
-                logger.error(f'{error} for l{self.l_addr} | '
+                logger.error(f'[{self.node_id}] {error} for l{self.l_addr} | '
                              f'r{self.r_addr}')
                 await self.disc()
                 self.close()
                 return self
 
             except RuntimeError as error:
-                logger.warning(f"{error} for {self.l_addr}")
+                logger.info(f"[{self.node_id}] {error} for {self.l_addr}")
                 await self.disc()
                 self.close()
                 return self

app/src/gen3/inverter_g3.py

@@ -56,7 +56,7 @@ class InverterG3(Inverter, ConnectionG3):
         addr = (host, port)
 
         try:
-            logging.info(f'Connected to {addr}')
+            logging.info(f'[{self.node_id}] Connected to {addr}')
             connect = asyncio.open_connection(host, port)
             reader, writer = await connect
             self.remoteStream = ConnectionG3(reader, writer, addr, self,

app/src/gen3/talent.py

@@ -63,6 +63,8 @@ class Talent(Message):
             0x04: logging.INFO,
         }
         self.modbus_elms = 0    # for unit tests
+        self.node_id = 'G3'     # will be overwritten in __set_serial_no
+        # self.forwarding = Config.get('tsun')['enabled']
 
     '''
     Our puplic methods
@@ -139,6 +141,8 @@ class Talent(Message):
 
     def send_modbus_cb(self, modbus_pdu: bytearray, log_lvl: int, state: str):
         if self.state != self.STATE_UP:
+            logger.warn(f'[{self.node_id}] ignore MODBUS cmd,'
+                        ' as the state is not UP')
             return
 
         self.__build_header(0x70, 0x77)
@@ -154,6 +158,8 @@ class Talent(Message):
 
     async def send_modbus_cmd(self, func, addr, val, log_lvl) -> None:
         if self.state != self.STATE_UP:
+            logger.warn(f'[{self.node_id}] ignore MODBUS cmd,'
+                        ' as the state is not UP')
             return
         self.mb.build_msg(Modbus.INV_ADDR, func, addr, val, log_lvl)
 

app/src/gen3plus/inverter_g3p.py

@@ -56,7 +56,7 @@ class InverterG3P(Inverter, ConnectionG3P):
         addr = (host, port)
 
         try:
-            logging.info(f'Connected to {addr}')
+            logging.info(f'[{self.node_id}] Connected to {addr}')
             connect = asyncio.open_connection(host, port)
             reader, writer = await connect
             self.remoteStream = ConnectionG3P(reader, writer, addr, self,

app/src/gen3plus/solarman_v5.py

@@ -122,6 +122,9 @@ class SolarmanV5(Message):
         if 'at_acl' in g3p_cnf:  # pragma: no cover
             self.at_acl = g3p_cnf['at_acl']
 
+        self.node_id = 'G3P'  # will be overwritten in __set_serial_no
+        # self.forwarding = Config.get('solarman')['enabled']
+
     '''
     Our puplic methods
     '''
@@ -336,6 +339,8 @@ class SolarmanV5(Message):
 
     def send_modbus_cb(self, pdu: bytearray, log_lvl: int, state: str):
         if self.state != self.STATE_UP:
+            logger.warn(f'[{self.node_id}] ignore MODBUS cmd,'
+                        ' as the state is not UP')
             return
         self.__build_header(0x4510)
         self._send_buffer += struct.pack('<BHLLL', self.MB_RTU_CMD,
@@ -349,6 +354,8 @@ class SolarmanV5(Message):
 
     async def send_modbus_cmd(self, func, addr, val, log_lvl) -> None:
         if self.state != self.STATE_UP:
+            logger.warn(f'[{self.node_id}] ignore MODBUS cmd,'
+                        ' as the state is not UP')
             return
         self.mb.build_msg(Modbus.INV_ADDR, func, addr, val, log_lvl)
 
@@ -358,6 +365,8 @@ class SolarmanV5(Message):
 
     async def send_at_cmd(self, AT_cmd: str) -> None:
         if self.state != self.STATE_UP:
+            logger.warn(f'[{self.node_id}] ignore AT+ cmd,'
+                        ' as the state is not UP')
             return
         AT_cmd = AT_cmd.strip()
 

app/src/messages.py

@@ -72,7 +72,7 @@ class Message(metaclass=IterRegistry):
         self.header_len = 0
         self.data_len = 0
         self.unique_id = 0
-        self.node_id = ''
+        self.node_id = ''  # will be overwritten in the child class's __init__
         self.sug_area = ''
         self._recv_buffer = bytearray(0)
         self._send_buffer = bytearray(0)