fix(logging): implement scoped logging (#152)

* fix(logging): implement scoped logging
* Fix f-string
* Apply suggestions from code review
* Update python/src/wslink/protocol.py

fix #151

python/src/wslink/backends/aiohttp/__init__.py

@@ -15,6 +15,8 @@
 MAX_MSG_SIZE = int(os.environ.get("WSLINK_MAX_MSG_SIZE", 4194304))
 HEART_BEAT = int(os.environ.get("WSLINK_HEART_BEAT", 30))  # 30 seconds
 
+logger = logging.getLogger(__name__)
+
 # -----------------------------------------------------------------------------
 # HTTP helpers
 # -----------------------------------------------------------------------------
@@ -98,31 +100,31 @@ async def start(self, port_callback=None):
             self.app, handle_signals=self.handle_signals
         )
 
-        logging.info("awaiting runner setup")
+        logger.info("awaiting runner setup")
         await self._runner.setup()
 
         self._site = aiohttp_web.TCPSite(
             self._runner, self.host, self.port, ssl_context=self.ssl_context
         )
 
-        logging.info("awaiting site startup")
+        logger.info("awaiting site startup")
         await self._site.start()
 
         if port_callback is not None:
             port_callback(self.get_port())
 
-        logging.info(f"Print WSLINK_READY_MSG")
+        logger.info("Print WSLINK_READY_MSG")
         STARTUP_MSG = os.environ.get("WSLINK_READY_MSG", "wslink: Starting factory")
         if STARTUP_MSG:
             # Emit an expected log message so launcher.py knows we've started up.
             print(STARTUP_MSG)
             # We've seen some issues with stdout buffering - be conservative.
             sys.stdout.flush()
 
-        logging.info(f"Schedule auto shutdown with timout {self.timeout}")
+        logger.info(f"Schedule auto shutdown with timout {self.timeout}")
         self.shutdown_schedule()
 
-        logging.info("awaiting running future")
+        logger.info("awaiting running future")
         await self.completion
 
     async def stop(self):
@@ -133,12 +135,12 @@ async def stop(self):
         # Neither site.stop() nor runner.cleanup() actually stop the server
         # as documented, but at least runner.cleanup() results in the
         # "on_shutdown" signal getting sent.
-        logging.info("Performing runner.cleanup()")
+        logger.info("Performing runner.cleanup()")
         await self.runner.cleanup()
 
         # So to actually stop the server, the workaround is just to resolve
         # the future we awaited in the start method.
-        logging.info("Stopping server")
+        logger.info("Stopping server")
         self.completion.set_result(True)
 
 
@@ -163,7 +165,7 @@ async def stop(self):
 
 def create_webserver(server_config):
     if "logging_level" in server_config and server_config["logging_level"]:
-        logging.basicConfig(level=server_config["logging_level"])
+        logging.getLogger("wslink").setLevel(server_config["logging_level"])
 
     # Shortcut for reverse connection
     if "reverse_url" in server_config:
@@ -184,10 +186,10 @@ def is_binary(msg):
 
 class AioHttpWsHandler(WslinkHandler):
     async def disconnectClients(self):
-        logging.info("Closing client connections:")
+        logger.info("Closing client connections:")
         keys = list(self.connections.keys())
         for client_id in keys:
-            logging.info("  {0}".format(client_id))
+            logger.info("  {0}".format(client_id))
             ws = self.connections[client_id]
             await ws.close(
                 code=aiohttp.WSCloseCode.GOING_AWAY, message="Server shutdown"
@@ -202,7 +204,7 @@ async def handleWsRequest(self, request):
         )
         self.connections[client_id] = current_ws
 
-        logging.info("client {0} connected".format(client_id))
+        logger.info("client {0} connected".format(client_id))
 
         self.web_app.shutdown_cancel()
 
@@ -217,31 +219,31 @@ async def handleWsRequest(self, request):
             del self.connections[client_id]
             self.authentified_client_ids.discard(client_id)
 
-            logging.info("client {0} disconnected".format(client_id))
+            logger.info("client {0} disconnected".format(client_id))
 
             if not self.connections:
-                logging.info("No more connections, scheduling shutdown")
+                logger.info("No more connections, scheduling shutdown")
                 self.web_app.shutdown_schedule()
 
         return current_ws
 
     async def reverse_connect_to(self, url):
-        logging.debug("reverse_connect_to: running with url %s", url)
+        logger.debug("reverse_connect_to: running with url %s", url)
         client_id = self.reverse_connection_client_id
         async with aiohttp.ClientSession() as session:
-            logging.debug("reverse_connect_to: client session started")
+            logger.debug("reverse_connect_to: client session started")
             async with session.ws_connect(url) as current_ws:
-                logging.debug("reverse_connect_to: ws started")
+                logger.debug("reverse_connect_to: ws started")
                 self.connections[client_id] = current_ws
-                logging.debug("reverse_connect_to: onConnect")
+                logger.debug("reverse_connect_to: onConnect")
                 await self.onConnect(url, client_id)
 
                 async for msg in current_ws:
                     if not current_ws.closed:
                         await self.onMessage(is_binary(msg), msg, client_id)
 
-                logging.debug("reverse_connect_to: onClose")
+                logger.debug("reverse_connect_to: onClose")
                 await self.onClose(client_id)
                 del self.connections[client_id]
 
-        logging.debug("reverse_connect_to: exited")
+        logger.debug("reverse_connect_to: exited")

python/src/wslink/backends/aiohttp/launcher.py

@@ -23,6 +23,8 @@
     STATUS_NOT_FOUND,
 )
 
+logger = logging.getLogger(__name__)
+
 # ===========================================================================
 # Launcher ENV configuration
 # ===========================================================================
@@ -50,7 +52,7 @@ def __init__(self, options, config):
     def __del__(self):
         try:
             # causes an exception when server is killed with Ctrl-C
-            logging.warning("Server factory shutting down. Stopping all processes")
+            logger.warning("Server factory shutting down. Stopping all processes")
         except:
             pass
 
@@ -141,17 +143,17 @@ async def handle_get(self, request):
 
         if not id:
             message = "id not provided in GET request"
-            logging.error(message)
+            logger.error(message)
             return aiohttp_web.json_response(
                 {"error": message}, status=STATUS_BAD_REQUEST
             )
 
-        logging.info("GET request received for id: %s" % id)
+        logger.info("GET request received for id: %s" % id)
 
         session = self.session_manager.getSession(id)
         if not session:
             message = "No session with id: %s" % id
-            logging.error(message)
+            logger.error(message)
             return aiohttp_web.json_response(
                 {"error": message}, status=STATUS_BAD_REQUEST
             )
@@ -170,17 +172,17 @@ async def handle_delete(self, request):
 
         if not id:
             message = "id not provided in DELETE request"
-            logging.error(message)
+            logger.error(message)
             return aiohttp_web.json_response(
                 {"error": message}, status=STATUS_BAD_REQUEST
             )
 
-        logging.info("DELETE request received for id: %s" % id)
+        logger.info("DELETE request received for id: %s" % id)
 
         session = self.session_manager.getSession(id)
         if not session:
             message = "No session with id: %s" % id
-            logging.error(message)
+            logger.error(message)
             return aiohttp_web.json_response(
                 {"error": message}, status=STATUS_NOT_FOUND
             )
@@ -190,7 +192,7 @@ async def handle_delete(self, request):
         self.process_manager.stopProcess(id)
 
         message = "Deleted session with id: %s" % id
-        logging.info(message)
+        logger.info(message)
 
         return aiohttp_web.json_response(session, status=STATUS_OK)
 
@@ -213,15 +215,17 @@ def startWebServer(options, config):
     # Setup logging
     logFileName = log_dir + os.sep + "launcherLog.log"
     formatting = "%(asctime)s:%(levelname)s:%(name)s:%(message)s"
-    logging.basicConfig(
-        level=logging.DEBUG, filename=logFileName, filemode="w", format=formatting
-    )
+    # create file handler which logs even debug messages
+    fh = logging.FileHandler(logFileName, mode="w")
+    fh.setLevel(logging.DEBUG)
+    fh.setFormatter(logging.Formatter(formatting))
+    logging.getLogger("wslink").addHandler(fh)
     if options.debug:
         console = logging.StreamHandler(sys.stdout)
         console.setLevel(logging.INFO)
         formatter = logging.Formatter(formatting)
         console.setFormatter(formatter)
-        logging.getLogger("").addHandler(console)
+        logging.getLogger("wslink").addHandler(console)
 
     web_app = aiohttp_web.Application()
 

python/src/wslink/backends/aiohttp/relay.py

@@ -377,8 +377,6 @@ def main(host=None, port=None, www_path=None, proxy_route=None, mode=None):
     if proxy_route is None:
         proxy_route = args.proxy_route
 
-    logging.basicConfig()
-
     # Manage routes
     routes = []
 

python/src/wslink/backends/generic/core.py

@@ -125,7 +125,7 @@ def startWebServer(*args, **kwargs):
 
 def create_webserver(server_config):
     if "logging_level" in server_config and server_config["logging_level"]:
-        logging.basicConfig(level=server_config["logging_level"])
+        logging.getLogger("wslink").setLevel(server_config["logging_level"])
 
     # Reverse connection
     if "reverse_url" in server_config:

python/src/wslink/launcher.py

@@ -16,6 +16,8 @@
 
 from wslink import backends
 
+logger = logging.getLogger(__name__)
+
 STATUS_OK = 200
 STATUS_BAD_REQUEST = 400
 STATUS_NOT_FOUND = 404
@@ -205,7 +207,7 @@ def checkSanitize(key_pair, sanitize):
             value = key_pair[key]
             if checkItem["type"] == "inList":
                 if not value in checkItem["list"]:
-                    logging.warning(
+                    logger.warning(
                         "key %s: sanitize %s with default" % (key, key_pair[key])
                     )
                     key_pair[key] = checkItem["default"]
@@ -214,7 +216,7 @@ def checkSanitize(key_pair, sanitize):
                     # User is responsible to add begin- and end- string symbols, to make sure entire string is matched.
                     checkItem["compiled"] = re.compile(checkItem["regexp"])
                 if checkItem["compiled"].match(value) == None:
-                    logging.warning(
+                    logger.warning(
                         "key %s: sanitize %s with default" % (key, key_pair[key])
                     )
                     key_pair[key] = checkItem["default"]
@@ -232,7 +234,7 @@ def replaceVariables(template_str, variable_list, sanitize):
         template_str = item_template.safe_substitute(key_pair)
 
     if "$" in template_str:
-        logging.error("Some properties could not be resolved: " + template_str)
+        logger.error("Some properties could not be resolved: " + template_str)
 
     return template_str
 
@@ -441,8 +443,8 @@ def startProcess(self, session):
                 )
                 self.processes[session["id"]] = proc
             except:
-                logging.error("The command line failed")
-                logging.error(" ".join(map(str, session["cmd"])))
+                logger.error("The command line failed")
+                logger.error(" ".join(map(str, session["cmd"])))
                 return None
 
         return proc

python/src/wslink/protocol.py

@@ -17,6 +17,8 @@
 # used in client JS code:
 CLIENT_ERROR = -32099
 
+logger = logging.getLogger(__name__)
+
 
 class AbstractWebApp:
     def __init__(self, server_config):
@@ -108,7 +110,7 @@ def shutdown_schedule(self):
 
     def shutdown_cancel(self):
         if self._shutdown_task is not None:
-            logging.info("Canceling shutdown task")
+            logger.info("Canceling shutdown task")
             self._shutdown_task.cancel()
             self._shutdown_task = None
 
@@ -252,7 +254,7 @@ async def onMessage(self, is_binary, msg, client_id):
             payload = payload.decode("utf-8")
 
         rpc = json.loads(payload)
-        logging.debug("wslink incoming msg %s" % self.payloadWithSecretStripped(rpc))
+        logger.debug("wslink incoming msg %s", self.payloadWithSecretStripped(rpc))
         if "id" not in rpc:
             # should be a binary attachment header
             if rpc.get("method") == "wslink.binary.attachment":
@@ -340,9 +342,9 @@ def findAttachments(o):
                 )
             except Exception as e_inst:
                 captured_trace = traceback.format_exc()
-                logging.error("Exception raised")
-                logging.error(repr(e_inst))
-                logging.error(captured_trace)
+                logger.error("Exception raised")
+                logger.error(repr(e_inst))
+                logger.error(captured_trace)
                 await self.sendWrappedError(
                     rpcid,
                     EXCEPTION_ERROR,

python/src/wslink/websocket.py

@@ -9,6 +9,8 @@
 from . import register as exportRpc
 from . import schedule_callback
 
+logger = logging.getLogger(__name__)
+
 
 # =============================================================================
 #
@@ -114,7 +116,7 @@ def unregisterLinkProtocol(self, protocol):
         try:
             self.linkProtocols.remove(protocol)
         except ValueError as e:
-            logging.error("Link protocol missing from registered list.")
+            logger.error("Link protocol missing from registered list.")
 
     def getLinkProtocols(self):
         return self.linkProtocols