don't send MODBUS request when state is not up (#147)

* adapt timings

* don't send MODBUS request when state is note up

* adapt unit test

CHANGELOG.md

@@ -7,6 +7,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [unreleased]
 
+- don't send MODBUS request when state is note up; adapt timeouts [#141](https://github.com/s-allius/tsun-gen3-proxy/issues/141)
 - build multi arch images with sboms [#144](https://github.com/s-allius/tsun-gen3-proxy/issues/144)
 - add timestamp to MQTT topics [#138](https://github.com/s-allius/tsun-gen3-proxy/issues/138)
 - improve the message handling, to avoid hangs

app/src/async_stream.py

@@ -17,10 +17,10 @@ class AsyncStream():
     '''maximum processing time for a received msg in sec'''
     MAX_START_TIME = 400
     '''maximum time without a received msg in sec'''
-    MAX_INV_IDLE_TIME = 90
+    MAX_INV_IDLE_TIME = 120
     '''maximum time without a received msg from the inverter in sec'''
-    MAX_CLOUD_IDLE_TIME = 360
+    MAX_DEF_IDLE_TIME = 360
-    '''maximum time without a received msg from cloud side in sec'''
+    '''maximum default time without a received msg in sec'''
 
     def __init__(self, reader: StreamReader, writer: StreamWriter,
                  addr) -> None:
@@ -37,11 +37,11 @@ class AsyncStream():
     def __timeout(self) -> int:
         if self.state == State.init or self.state == State.received:
             to = self.MAX_START_TIME
+        elif self.state == State.up and \
+                self.server_side and self.modbus_polling:
+            to = self.MAX_INV_IDLE_TIME
         else:
-            if self.server_side and self.modbus_polling:
+            to = self.MAX_DEF_IDLE_TIME
-                to = self.MAX_INV_IDLE_TIME
-            else:
-                to = self.MAX_CLOUD_IDLE_TIME
         return to
 
     async def publish_outstanding_mqtt(self):

app/src/gen3/talent.py

@@ -45,7 +45,7 @@ class Talent(Message):
     MB_REGULAR_TIMEOUT = 60
 
     def __init__(self, server_side: bool, id_str=b''):
-        super().__init__(server_side, self.send_modbus_cb, mb_timeout=11)
+        super().__init__(server_side, self.send_modbus_cb, mb_timeout=15)
         self.await_conn_resp_cnt = 0
         self.id_str = id_str
         self.contact_name = b''
@@ -388,10 +388,6 @@ class Talent(Message):
             if self.data_len == 0:
                 if self.state == State.up:
                     self.state = State.pend     # block MODBUS cmds
-                if (self.modbus_polling):
-                    self.mb_timer.start(self.mb_start_timeout)
-                    self.db.set_db_def_value(Register.POLLING_INTERVAL,
-                                             self.mb_timeout)
 
                 ts = self._timestamp()
                 logger.debug(f'time: {ts:08x}')
@@ -455,6 +451,10 @@ class Talent(Message):
             self.__finish_send_msg()
             self.__process_data()
             self.state = State.up  # allow MODBUS cmds
+            if (self.modbus_polling):
+                self.mb_timer.start(self.mb_start_timeout)
+                self.db.set_db_def_value(Register.POLLING_INTERVAL,
+                                         self.mb_timeout)
 
         elif self.ctrl.is_resp():
             return  # ignore received response

app/src/modbus.py

@@ -106,6 +106,7 @@ class Modbus():
         self.loop = asyncio.get_event_loop()
         self.req_pend = False
         self.tim = None
+        self.node_id = ''
 
     def close(self):
         """free the queue and erase the callback handlers"""
@@ -180,6 +181,8 @@ class Modbus():
             5: No MODBUS request pending
         """
         # logging.info(f'recv_resp: first byte modbus:{buf[0]} len:{len(buf)}')
+        self.node_id = node_id
+
         if not self.req_pend:
             self.err = 5
             return
@@ -267,7 +270,10 @@ class Modbus():
             self.__start_timer()
             self.snd_handler(self.last_req, self.last_log_lvl, state='Retrans')
         else:
-            logger.info(f'Modbus timeout {self}')
+            logger.info(f'[{self.node_id}] Modbus timeout '
+                        f'(FCode: {self.last_fcode} '
+                        f'Reg: 0x{self.last_reg:04x}, '
+                        f'{self.last_len})')
             self.counter['timeouts'] += 1
             self.__send_next_from_que()
 

app/tests/test_talent.py

@@ -1587,11 +1587,11 @@ def test_modbus_no_polling(ConfigNoMbPoll, MsgGetTime):
     m.close()
 
 @pytest.mark.asyncio
-async def test_modbus_polling(ConfigTsunInv1, MsgGetTime):
+async def test_modbus_polling(ConfigTsunInv1, MsgInverterInd):
     ConfigTsunInv1
     assert asyncio.get_running_loop()
 
-    m = MemoryStream(MsgGetTime, (0,))
+    m = MemoryStream(MsgInverterInd, (0,))
     assert asyncio.get_running_loop() == m.mb_timer.loop
     m.db.stat['proxy']['Unknown_Ctrl'] = 0
     assert m.mb_timer.tim == None
@@ -1601,16 +1601,16 @@ async def test_modbus_polling(ConfigTsunInv1, MsgGetTime):
     assert m.id_str == b"R170000000000001" 
     assert m.unique_id == 'R170000000000001'
     assert int(m.ctrl)==145
-    assert m.msg_id==34
+    assert m.msg_id==4
     assert m.header_len==23
     assert m.ts_offset==0
-    assert m.data_len==0
+    assert m.data_len==120
-    assert m._forward_buffer==MsgGetTime
+    assert m._forward_buffer==MsgInverterInd
-    assert m._send_buffer==b'\x00\x00\x00\x1b\x10R170000000000001\x91"\x00\x00\x01\x89\xc6,_\x00'
+    assert m._send_buffer==b'\x00\x00\x00\x14\x10R170000000000001\x99\x04\x01'
     assert m.db.stat['proxy']['Unknown_Ctrl'] == 0
 
     m._send_buffer = bytearray(0) # clear send buffer for next test
-    m.state = State.up
+    #  m.state = State.up
     assert m.mb_timeout == 0.5
     assert next(m.mb_timer.exp_count) == 0