Fix #221 timing enhancements, #188 workarounds

Author: dhoomakethu

examples/contrib/message_parser.py

@@ -144,14 +144,6 @@ def get_options():
                       help="If the incoming message is in hexadecimal format",
                       action="store_true", dest="transaction", default=False)
 
-    parser.add_option("-t", "--transaction",
-        help="If the incoming message is in hexadecimal format",
-        action="store_true", dest="transaction", default=False)
-
-    parser.add_option("-t", "--transaction",
-        help="If the incoming message is in hexadecimal format",
-        action="store_true", dest="transaction", default=False)
-
     (opt, arg) = parser.parse_args()
 
     if not opt.message and len(arg) > 0:

pymodbus/client/sync.py

@@ -324,11 +324,12 @@ def __init__(self, method='ascii', **kwargs):
         self.baudrate = kwargs.get('baudrate', Defaults.Baudrate)
         self.timeout = kwargs.get('timeout',  Defaults.Timeout)
         if self.method == "rtu":
-            self._last_frame_end = 0.0
+            self._last_frame_end = None
             if self.baudrate > 19200:
                 self._silent_interval = 1.75/1000  # ms
             else:
                 self._silent_interval = 3.5 * (1 + 8 + 2) / self.baudrate
+            self._silent_interval = round(self._silent_interval, 6)
 
     @staticmethod
     def __implementation(method):
@@ -353,7 +354,8 @@ def connect(self):
 
         :returns: True if connection succeeded, False otherwise
         """
-        if self.socket: return True
+        if self.socket:
+            return True
         try:
             self.socket = serial.Serial(port=self.port,
                                         timeout=self.timeout,
@@ -390,26 +392,30 @@ def _send(self, request):
                       "state - {}".format(TransactionStateString[self.state]))
         while self.state != ModbusTransactionState.IDLE:
             if self.state == ModbusTransactionState.TRANSCATION_COMPLETE:
+                ts = round(time.time(), 6)
+                _logger.debug("Changing state to IDLE - Last Frame End - {}, "
+                              "Current Time stamp - {}".format(
+                    self._last_frame_end, ts))
+                if self.method == "rtu":
+                    if self._last_frame_end:
+                        idle_time = self._last_frame_end + self._silent_interval
+                        if round(ts-idle_time, 6) <= self._silent_interval:
+                            _logger.debug("Waiting for 3.5 char before next "
+                                          "send - {} ms".format(
+                                self._silent_interval*1000))
+                            time.sleep(self._silent_interval)
+                    else:
+                        # Recovering from last error ??
+                        time.sleep(self._silent_interval)
                 self.state = ModbusTransactionState.IDLE
             else:
+                _logger.debug("Sleeping")
                 time.sleep(self._silent_interval)
         _logger.debug("Transaction state 'IDLE', intiating a new transaction")
         self.state = ModbusTransactionState.SENDING
         if not self.socket:
             raise ConnectionException(self.__str__())
         if request:
-            ts = time.time()
-            if self.method == "rtu":
-                if self._last_frame_end:
-                    if ts < self._last_frame_end + self._silent_interval:
-                        _logger.debug("waiting for 3.5 char before next "
-                                      "send".format(self._silent_interval))
-                        time.sleep(
-                            self._last_frame_end + self._silent_interval - ts
-                        )
-                        _logger.debug("waited for - {} "
-                                      "ms".format(self._silent_interval*1000))
-
             try:
                 in_waiting = ("in_waiting" if hasattr(
                     self.socket, "in_waiting") else "inWaiting")
@@ -431,7 +437,7 @@ def _send(self, request):
                           "to 'WAITING FOR REPLY'")
             self.state = ModbusTransactionState.WAITING_FOR_REPLY
             if self.method == "rtu":
-                self._last_frame_end = time.time()
+                self._last_frame_end = round(time.time(), 6)
             return size
         return 0
 
@@ -444,11 +450,12 @@ def _recv(self, size):
         if not self.socket:
             raise ConnectionException(self.__str__())
         result = self.socket.read(size)
-        _logger.debug("Changing transaction state from 'WAITING FOR REPLY' "
-                      "to 'PROCESSING REPLY'")
-        self.state = ModbusTransactionState.PROCESSING_REPLY
+        if self.state != ModbusTransactionState.PROCESSING_REPLY:
+            _logger.debug("Changing transaction state from "
+                          "'WAITING FOR REPLY' to 'PROCESSING REPLY'")
+            self.state = ModbusTransactionState.PROCESSING_REPLY
         if self.method == "rtu":
-            self._last_frame_end = time.time()
+            self._last_frame_end = round(time.time(), 6)
         return result
 
     def __str__(self):

pymodbus/transaction.py

@@ -116,62 +116,70 @@ def execute(self, request):
         consumer.write(Frame(request))
         '''
         with self._transaction_lock:
-            retries = self.retries
-            request.transaction_id = self.getNextTID()
-            _logger.debug("Running transaction %d" % request.transaction_id)
-            _buffer = hexlify_packets(self.client.framer._buffer)
-            _logger.debug("Current Frame : - {}".format(_buffer))
-            expected_response_length = None
-            if not isinstance(self.client.framer, ModbusSocketFramer):
-                if hasattr(request, "get_response_pdu_size"):
-                    response_pdu_size = request.get_response_pdu_size()
-                    if isinstance(self.client.framer, ModbusAsciiFramer):
-                        response_pdu_size = response_pdu_size * 2
-                    if response_pdu_size:
-                        expected_response_length = self._calculate_response_length(response_pdu_size)
-            if request.unit_id in self._no_response_devices:
-                full = True
-            else:
-                full = False
-            response, last_exception = self._transact(request,
-                                                      expected_response_length,
-                                                      full=full
-                                                      )
-            if not response and (
-                    request.unit_id not in self._no_response_devices):
-                self._no_response_devices.append(request.unit_id)
-            elif request.unit_id in self._no_response_devices:
-                self._no_response_devices.remove(request.unit_id)
-            if not response and self.retry_on_empty and retries:
-                while retries > 0:
-                    if hasattr(self.client, "state"):
-                        _logger.debug("RESETTING Transaction state to "
-                                      "'IDLE' for retry")
-                        self.client.state = ModbusTransactionState.IDLE
-                    _logger.debug("Retry on empty - {}".format(retries))
-                    response, last_exception = self._transact(
-                        request,
-                        expected_response_length
-                    )
-                    if not response:
-                        retries -= 1
-                        continue
-                    break
-            self.client.framer.processIncomingPacket(response,
-                                                     self.addTransaction)
-            response = self.getTransaction(request.transaction_id)
-            if not response:
-                if len(self.transactions):
-                    response = self.getTransaction(tid=0)
+            try:
+                retries = self.retries
+                request.transaction_id = self.getNextTID()
+                _logger.debug("Running transaction %d" % request.transaction_id)
+                _buffer = hexlify_packets(self.client.framer._buffer)
+                if _buffer:
+                    _logger.debug("Clearing current Frame : - {}".format(_buffer))
+                    self.client.framer.resetFrame()
+
+                expected_response_length = None
+                if not isinstance(self.client.framer, ModbusSocketFramer):
+                    if hasattr(request, "get_response_pdu_size"):
+                        response_pdu_size = request.get_response_pdu_size()
+                        if isinstance(self.client.framer, ModbusAsciiFramer):
+                            response_pdu_size = response_pdu_size * 2
+                        if response_pdu_size:
+                            expected_response_length = self._calculate_response_length(response_pdu_size)
+                if request.unit_id in self._no_response_devices:
+                    full = True
                 else:
-                    last_exception = last_exception or ("No Response received "
-                                                        "from the remote unit")
-                    response = ModbusIOException(last_exception)
-            if hasattr(self.client, "state"):
-                _logger.debug("Changing transaction state from "
-                              "'PROCESSING REPLY' to 'TRANSCATION_COMPLETE'")
+                    full = False
+                response, last_exception = self._transact(request,
+                                                          expected_response_length,
+                                                          full=full
+                                                          )
+                if not response and (
+                        request.unit_id not in self._no_response_devices):
+                    self._no_response_devices.append(request.unit_id)
+                elif request.unit_id in self._no_response_devices:
+                    self._no_response_devices.remove(request.unit_id)
+                if not response and self.retry_on_empty and retries:
+                    while retries > 0:
+                        if hasattr(self.client, "state"):
+                            _logger.debug("RESETTING Transaction state to "
+                                          "'IDLE' for retry")
+                            self.client.state = ModbusTransactionState.IDLE
+                        _logger.debug("Retry on empty - {}".format(retries))
+                        response, last_exception = self._transact(
+                            request,
+                            expected_response_length
+                        )
+                        if not response:
+                            retries -= 1
+                            continue
+                        break
+                self.client.framer.processIncomingPacket(response,
+                                                         self.addTransaction)
+                response = self.getTransaction(request.transaction_id)
+                if not response:
+                    if len(self.transactions):
+                        response = self.getTransaction(tid=0)
+                    else:
+                        last_exception = last_exception or ("No Response received "
+                                                            "from the remote unit")
+                        response = ModbusIOException(last_exception)
+                if hasattr(self.client, "state"):
+                    _logger.debug("Changing transaction state from "
+                                  "'PROCESSING REPLY' to 'TRANSCATION_COMPLETE'")
+                    self.client.state = ModbusTransactionState.TRANSCATION_COMPLETE
+                return response
+            except Exception as ex:
+                _logger.exception(ex)
                 self.client.state = ModbusTransactionState.TRANSCATION_COMPLETE
-            return response
+                raise
 
     def _transact(self, packet, response_length, full=False):
         """
@@ -187,11 +195,11 @@ def _transact(self, packet, response_length, full=False):
             self.client.connect()
             packet = self.client.framer.buildPacket(packet)
             if _logger.isEnabledFor(logging.DEBUG):
-                _logger.debug("send: " + hexlify_packets(packet))
+                _logger.debug("SEND: " + hexlify_packets(packet))
             self._send(packet)
             result = self._recv(response_length or 1024, full)
             if _logger.isEnabledFor(logging.DEBUG):
-                _logger.debug("recv: " + hexlify_packets(result))
+                _logger.debug("RECV: " + hexlify_packets(result))
         except (socket.error, ModbusIOException,
                 InvalidMessageRecievedException) as msg:
             self.client.close()
@@ -240,12 +248,22 @@ def _recv(self, expected_response_length, full):
                         length = struct.unpack(">H", read_min[4:6])[0] - 1
                         expected_response_length = h_size + length
                     expected_response_length -= min_size
+                    total = expected_response_length + min_size
                 else:
                     expected_response_length = exception_length - min_size
+                    total = expected_response_length + min_size
+            else:
+                total = expected_response_length
         else:
             read_min = b''
+            total = expected_response_length
         result = self.client._recv(expected_response_length)
         result = read_min + result
+        actual = len(result)
+        if actual != total:
+            _logger.debug("Incomplete message received, "
+                          "Expected {} bytes Recieved "
+                          "{} bytes !!!!".format(total, actual))
         return result
 
     def addTransaction(self, request, tid=None):
@@ -322,7 +340,7 @@ def addTransaction(self, request, tid=None):
         :param tid: The overloaded transaction id to use
         '''
         tid = tid if tid != None else request.transaction_id
-        _logger.debug("adding transaction %d" % tid)
+        _logger.debug("Adding transaction %d" % tid)
         self.transactions[tid] = request
 
     def getTransaction(self, tid):
@@ -332,15 +350,15 @@ def getTransaction(self, tid):
 
         :param tid: The transaction to retrieve
         '''
-        _logger.debug("getting transaction %d" % tid)
+        _logger.debug("Getting transaction %d" % tid)
         return self.transactions.pop(tid, None)
 
     def delTransaction(self, tid):
         ''' Removes a transaction matching the referenced tid
 
         :param tid: The transaction to remove
         '''
-        _logger.debug("deleting transaction %d" % tid)
+        _logger.debug("Deleting transaction %d" % tid)
         self.transactions.pop(tid, None)
 
 
@@ -374,7 +392,7 @@ def addTransaction(self, request, tid=None):
         :param tid: The overloaded transaction id to use
         '''
         tid = tid if tid != None else request.transaction_id
-        _logger.debug("adding transaction %d" % tid)
+        _logger.debug("Adding transaction %d" % tid)
         self.transactions.append(request)
 
     def getTransaction(self, tid):
@@ -384,15 +402,15 @@ def getTransaction(self, tid):
 
         :param tid: The transaction to retrieve
         '''
-        _logger.debug("getting transaction %s" % str(tid))
+        _logger.debug("Getting transaction %s" % str(tid))
         return self.transactions.pop(0) if self.transactions else None
 
     def delTransaction(self, tid):
         ''' Removes a transaction matching the referenced tid
 
         :param tid: The transaction to remove
         '''
-        _logger.debug("deleting transaction %d" % tid)
+        _logger.debug("Deleting transaction %d" % tid)
         if self.transactions: self.transactions.pop(0)
 
 
@@ -713,7 +731,7 @@ def getFrame(self):
         if end > 0:
             _logger.debug("Getting Frame - {}".format(hexlify_packets(buffer)))
             return buffer
-        return ''
+        return b''
 
     def populateResult(self, result):
         ''' Populates the modbus result header

test/test_client_sync.py

@@ -204,9 +204,9 @@ def testSyncSerialClientInstantiation(self):
 
     def testSyncSerialRTUClientTimeouts(self):
         client = ModbusSerialClient(method="rtu", baudrate=9600)
-        assert client._silent_interval == (3.5 * 11/9600)
+        assert client._silent_interval == round((3.5 * 11/9600), 6)
         client = ModbusSerialClient(method="rtu", baudrate=38400)
-        assert client._silent_interval == (1.75/1000)
+        assert client._silent_interval == round((1.75/1000), 6)
 
 
     @patch("serial.Serial")