S allius/issue102 (#110)

* hotfix: don't send two MODBUS commands together

* fix unit tests

* remove read loop

* optional sleep between msg read and sending rsp

* wait after read 0.5s before sending a response

* add pending state

* fix state definitions

* determine the connection timeout by the conn state

* avoid sending MODBUS cmds in the inverter's reporting phase

* update changelog

CHANGELOG.md

@@ -7,6 +7,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [unreleased]
 
+- GEN3: avoid sending MODBUS commands to the inverter during the inverter's reporting phase
+- GEN3: determine the connection timeout based on the connection state
 - GEN3: support more data encodings for DSP version V5.0.17 [#108](https://github.com/s-allius/tsun-gen3-proxy/issues/108)
 - detect dead connections [#100](https://github.com/s-allius/tsun-gen3-proxy/issues/100)
 - improve connection logging wirt a unique connection id

app/src/async_stream.py

@@ -15,7 +15,9 @@ class AsyncStream():
     _ids = count(0)
     MAX_PROC_TIME = 2
     '''maximum processing time for a received msg in sec'''
-    MAX_IDLE_TIME = 400
+    MAX_START_TIME = 400
+    '''maximum time without a received msg in sec'''
+    MAX_IDLE_TIME = 90
     '''maximum time without a received msg in sec'''
 
     def __init__(self, reader: StreamReader, writer: StreamWriter,
@@ -30,6 +32,12 @@ class AsyncStream():
         self.proc_start = None  # start processing start timestamp
         self.proc_max = 0
 
+    def __timeout(self):
+        if self.state == State.init:
+            self.MAX_START_TIME
+        else:
+            self.MAX_IDLE_TIME
+
     async def server_loop(self, addr: str) -> None:
         '''Loop for receiving messages from the inverter (server-side)'''
         logger.info(f'[{self.node_id}:{self.conn_no}] '
@@ -85,7 +93,8 @@ class AsyncStream():
                     self.proc_max = proc
                 self.proc_start = None
 
-                await asyncio.wait_for(self.__async_read(), self.MAX_IDLE_TIME)
+                await asyncio.wait_for(self.__async_read(),
+                                       self.__timeout())
 
                 if self.unique_id:
                     await self.async_write()
@@ -169,7 +178,9 @@ class AsyncStream():
         if data:
             self.proc_start = time.time()
             self._recv_buffer += data
-            self.read()                # call read in parent class
+            wait = self.read()                # call read in parent class
+            if wait > 0:
+                await asyncio.sleep(wait)
         else:
             raise RuntimeError("Peer closed.")
 

app/src/gen3/talent.py

@@ -106,7 +106,7 @@ class Talent(Message):
 
             self.unique_id = serial_no
 
-    def read(self) -> None:
+    def read(self) -> float:
         self._read()
 
         if not self.header_valid:
@@ -115,7 +115,7 @@ class Talent(Message):
         if self.header_valid and len(self._recv_buffer) >= (self.header_len +
                                                             self.data_len):
             if self.state == State.init:
-                self.state = State.received
+                self.state = State.received     # received 1st package
 
             log_lvl = self.log_lvl.get(self.msg_id, logging.WARNING)
             if callable(log_lvl):
@@ -127,7 +127,7 @@ class Talent(Message):
             self.__set_serial_no(self.id_str.decode("utf-8"))
             self.__dispatch_msg()
             self.__flush_recv_msg()
-        return
+        return 0.5  # wait 500ms before sending a response
 
     def forward(self, buffer, buflen) -> None:
         tsun = Config.get('tsun')
@@ -278,7 +278,8 @@ class Talent(Message):
         fnc = self.switch.get(self.msg_id, self.msg_unknown)
         if self.unique_id:
             logger.info(self.__flow_str(self.server_side, 'rx') +
-                        f' Ctl: {int(self.ctrl):#02x} Msg: {fnc.__name__!r}')
+                        f' Ctl: {int(self.ctrl):#02x} ({self.state}) '
+                        f'Msg: {fnc.__name__!r}')
             fnc()
         else:
             logger.info(self.__flow_str(self.server_side, 'drop') +
@@ -329,6 +330,7 @@ class Talent(Message):
     def msg_get_time(self):
         if self.ctrl.is_ind():
             if self.data_len == 0:
+                self.state = State.pend     # block MODBUS cmds
                 ts = self._timestamp()
                 logger.debug(f'time: {ts:08x}')
                 self.__build_header(0x91)
@@ -374,7 +376,6 @@ class Talent(Message):
             self._send_buffer += b'\x01'
             self.__finish_send_msg()
             self.__process_data()
-            self.state = State.up
 
         elif self.ctrl.is_resp():
             return  # ignore received response
@@ -390,7 +391,7 @@ class Talent(Message):
             self._send_buffer += b'\x01'
             self.__finish_send_msg()
             self.__process_data()
-            self.state = State.up
+            self.state = State.up  # allow MODBUS cmds
 
         elif self.ctrl.is_resp():
             return  # ignore received response

app/src/gen3plus/solarman_v5.py

@@ -169,7 +169,7 @@ class SolarmanV5(Message):
 
             self.unique_id = serial_no
 
-    def read(self) -> None:
+    def read(self) -> float:
         self._read()
 
         if not self.header_valid:
@@ -190,7 +190,7 @@ class SolarmanV5(Message):
                 self.__set_serial_no(self.snr)
                 self.__dispatch_msg()
             self.__flush_recv_msg()
-        return
+        return 0  # wait 0s before sending a response
 
     def forward(self, buffer, buflen) -> None:
         tsun = Config.get('solarman')

app/src/messages.py

@@ -61,7 +61,9 @@ class State(Enum):
     '''at least one packet received'''
     up = 2
     '''at least one cmd-rsp transaction'''
-    closed = 3
+    pend = 3
+    '''inverter transaction pending, don't send MODBUS cmds'''
+    closed = 4
     '''connection closed'''
 
 

app/tests/test_solarman.py

@@ -852,8 +852,7 @@ def test_read_message_in_chunks2(ConfigTsunInv1, DeviceIndMsg):
     assert m.data_len == 0xd4
     assert m.msg_count == 1
     assert m.db.stat['proxy']['Invalid_Msg_Format'] == 0
-    while m.read(): # read rest of message
+    m.read()        # read rest of message
-        pass
     assert m.msg_count == 1
     assert not m.header_valid  # must be invalid, since msg was handled and buffer flushed
     assert m.db.stat['proxy']['Invalid_Msg_Format'] == 0

app/tests/test_talent.py

@@ -435,8 +435,7 @@ def test_read_message_in_chunks2(MsgContactInfo):
     assert int(m.ctrl)==145
     assert m.msg_id==0 
     assert m.msg_count == 1
-    while m.read(): # read rest of message
+    m.read()         # read rest of message
-        pass
     assert m.msg_count == 1
     assert not m.header_valid  # must be invalid, since msg was handled and buffer flushed
     m.close()
@@ -807,6 +806,29 @@ def test_msg_inv_ind2(ConfigTsunInv1, MsgInverterIndNew, MsgInverterIndTsOffs, M
     assert m._send_buffer==MsgInverterAck
     m.close()
 
+def test_msg_inv_ind2(ConfigTsunInv1, MsgInverterIndNew, MsgInverterIndTsOffs, MsgInverterAck):
+    ConfigTsunInv1
+    tracer.setLevel(logging.DEBUG)
+    m = MemoryStream(MsgInverterIndNew, (0,))
+    m.db.stat['proxy']['Unknown_Ctrl'] = 0
+    m.db.stat['proxy']['Invalid_Data_Type'] = 0
+    m.read()         # read complete msg, and dispatch msg
+    assert m.db.stat['proxy']['Unknown_Ctrl'] == 0
+    assert m.db.stat['proxy']['Invalid_Data_Type'] == 0
+    assert not m.header_valid  # must be invalid, since msg was handled and buffer flushed
+    assert m.msg_count == 1
+    assert m.id_str == b"R170000000000001" 
+    assert m.unique_id == 'R170000000000001'
+    assert int(m.ctrl)==145
+    assert m.msg_id==4
+    assert m.header_len==23
+    assert m.data_len==1165
+    m.ts_offset = 0
+    m._update_header(m._forward_buffer)
+    assert m._forward_buffer==MsgInverterIndNew
+    assert m._send_buffer==MsgInverterAck
+    m.close()
+
 def test_msg_inv_ack(ConfigTsunInv1, MsgInverterAck):
     ConfigTsunInv1
     tracer.setLevel(logging.ERROR)