Add lock counter and logs

.gitignore

@@ -37,3 +37,9 @@ rabbitmq-server.download.tar.xz
 /MagicMock/mock/
 /docs/source/volttron_api/
 Pipfile
+modbus_configs
+modbus_tk_configs
+activateenv
+volttron.service
+upgrade-scripts
+volttron_modbus.log

services/core/PlatformDriverAgent/platform_driver/driver.py

@@ -245,10 +245,14 @@ def periodic_read(self, now):
             register_names = self.interface.get_register_names_view()
             _log.debug(f"results keys: {results.keys}")
             _log.debug(f"register_names keys: {register_names}")
+            # register_names contains list of all points
+            # results.keys gives points from the device 
+            # The following loop will check if there are more points from the device than what
+            # was expected and then log an error
             for point in (register_names - results.keys()):
                 _log.debug(f"Scraping point: {point}")
                 depth_first_topic = self.base_topic(point=point)
-                _log.error("Failed to scrape point: "+depth_first_topic)
+                _log.error(f"Failed to scrape point: {depth_first_topic}")
         except (Exception, gevent.Timeout) as ex:
             tb = traceback.format_exc()
             _log.error('Failed to scrape ' + self.device_name + ':\n' + tb)

services/core/PlatformDriverAgent/platform_driver/driver_locks.py

@@ -90,6 +90,7 @@ def publish_lock():
         _publish_lock.release()
 
 _client_socket_locks  = defaultdict(lambda: None)
+lock_counter = 0
 
 def configure_client_socket_lock(address, port, max_connections=0):
     _log.debug("Configuring client socket lock for {}:{}".format(address, port))
@@ -117,8 +118,14 @@ def client_socket_locks(address, port):
         _log.debug(f"lock is None: lock: {lock}, type: {type(lock)}, id ${id(lock)}")
         raise RuntimeError("socket_lock not configured!")
     lock.acquire()
+    global lock_counter
+    lock_counter +=1
+    _log.debug(f"lock_counter: {lock_counter}")
+
     try:
         yield
     finally:
         _log.debug(f"Releasing client socket lock ({type(lock)}) for {address}:{port} at {id(lock)}")
         lock.release()
+        lock_counter -=1
+        _log.debug(f"lock_counter after release: {lock_counter}")

services/core/PlatformDriverAgent/platform_driver/interfaces/modbus_tk/client.py

@@ -77,7 +77,6 @@ class MyModbusMaster (Client):
 
 from . import helpers
 
-
 # utils.setup_logging()
 # _log = logging.getLogger(__name__)
 logger = logging.getLogger(__name__)
@@ -679,28 +678,62 @@ def get_request(self, field):
         return self.__meta[helpers.META_REQUEST_MAP].get(field, None)
 
     def read_request(self, request):
-        try:
-            results = self.client.execute(
-                self.slave_address,
-                request.read_function_code,
-                request.address,
-                quantity_of_x=request.count,
-                data_format=request.formatting,
-                threadsafe=False
-            )
-            logger.debug("Successfully read the request...")
-            self._data.update(request.parse_values(results))
-        except (AttributeError, ModbusError) as err:
-            if "Exception code" in err.message:
-                msg = "{0}: {1}".format(err.message,
-                                                  helpers.TABLE_EXCEPTION_CODE.get(err.message[-1], "UNDEFINED"))
-                logger.debug(msg)
-                raise Exception("{0}: {1}".format(msg))
-            logger.warning("modbus read_all() failure on request: %s\tError: %s", request, err)
+        results = self.client.execute(
+            self.slave_address,
+            request.read_function_code,
+            request.address,
+            quantity_of_x=request.count,
+            data_format=request.formatting,
+            threadsafe=False
+        )
+        logger.debug("Successfully read the request...")
+        self._data.update(request.parse_values(results))
+        # try:
+        #     results = self.client.execute(
+        #         self.slave_address,
+        #         request.read_function_code,
+        #         request.address,
+        #         quantity_of_x=request.count,
+        #         data_format=request.formatting,
+        #         threadsafe=False
+        #     )
+        #     logger.debug("Successfully read the request...")
+        #     self._data.update(request.parse_values(results))
+        # except (AttributeError, ModbusError) as err:
+        #     if "Exception code" in err.message:
+        #         msg = "{0}: {1}".format(err.message,
+        #                                           helpers.TABLE_EXCEPTION_CODE.get(err.message[-1], "UNDEFINED"))
+        #         logger.debug(msg)
+        #         raise Exception("{0}: {1}".format(msg))
+        #     logger.warning("modbus read_all() failure on request: %s\tError: %s", request, err)
+
+
+    def timer(slogger):
+        """Print the runtime of the decorated function"""
+        from functools import wraps
+        import time
+        def decorator_timer(func):
+            @wraps(func)
+            def wrapper_timer(*args, **kwargs):
+                start_time = datetime.now()  # 1
+                value = func(*args, **kwargs)
+                end_time = datetime.now()  # 2
+                run_time_sec = end_time - start_time
+                slogger.debug(
+                    f"Finished {func.__name__!r} in {run_time_sec.total_seconds()} seconds"
+                )
+                return value
 
+            return wrapper_timer
+
+        return decorator_timer
+
+    @timer(logger)
     def read_all(self):
+        logger.debug(f"READ_ALL Time now: {datetime.now()}")
         requests = self.__meta[helpers.META_REQUESTS]
         self._data.clear()
+        # gets the lock
         with client_socket_locks(self.device_address, self.port):
             logger.debug(f"Entered lock for {self.device_address}:{self.port}-{self.slave_address}")
             logger.debug(f"Total requests to be read: {len(requests)}")
@@ -712,7 +745,7 @@ def read_all(self):
                     exception_flag = False
                     try:
                         self.read_request(r)
-                        break
+                        break # can use break or continue
                     except ConnectionResetError:
                         exception_flag = True
                         logger.warning("ConnectionResetError on read_request()")
@@ -721,19 +754,25 @@ def read_all(self):
                         exception_flag = True
                         logger.warning("ModbusInvalidResponseError on read_request()")
                         logger.warning(f"Error response: {e}")
-                    if exception_flag:
-                        self.client.close()
-                        gevent.sleep(1.0)
-                        self.client.open()
+                    except Exception as e:
+                        exception_flag = True
+                        logger.warning("CATCHING ALL EXCEPTIONS")
+                        logger.warning(f"Error response: {e}")
+                    # if exception_flag:
+                    #     logger.warning("CLOSING SOCKET CONNECTION")
+                    #     self.client.close()
+                    #     gevent.sleep(1.0)
+                    #     logger.warning("OPENING SOCKET CONNECTION")
+                    #     self.client.open()
                     retries -= 1
 
                 if retries == 0:
                     logger.debug(f"Failed to read request: {r}")
                 else:
                     logger.debug(f"Succesfully read the request on retry: {retries}")
-
         logger.debug(f"left lock for {self.device_address}:{self.port}-{self.slave_address}")
 
+    @timer(logger)    
     def dump_all(self):
         self.read_all()
         return [(f,