diff --git a/python/src/wslink/backends/aiohttp/__init__.py b/python/src/wslink/backends/aiohttp/__init__.py index ecde93dc..d85ca4ff 100644 --- a/python/src/wslink/backends/aiohttp/__init__.py +++ b/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,20 +100,20 @@ 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. @@ -119,10 +121,10 @@ async def start(self, port_callback=None): # 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") diff --git a/python/src/wslink/backends/aiohttp/launcher.py b/python/src/wslink/backends/aiohttp/launcher.py index b36bef50..8a43164f 100644 --- a/python/src/wslink/backends/aiohttp/launcher.py +++ b/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() diff --git a/python/src/wslink/backends/aiohttp/relay.py b/python/src/wslink/backends/aiohttp/relay.py index 08e4ffa7..04e90f05 100644 --- a/python/src/wslink/backends/aiohttp/relay.py +++ b/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 = [] diff --git a/python/src/wslink/backends/generic/core.py b/python/src/wslink/backends/generic/core.py index ec72dc08..ecc6b2fd 100644 --- a/python/src/wslink/backends/generic/core.py +++ b/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: diff --git a/python/src/wslink/launcher.py b/python/src/wslink/launcher.py index ee4a1d2c..d1bb1659 100755 --- a/python/src/wslink/launcher.py +++ b/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 diff --git a/python/src/wslink/protocol.py b/python/src/wslink/protocol.py index a634f398..e2642d95 100644 --- a/python/src/wslink/protocol.py +++ b/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, diff --git a/python/src/wslink/websocket.py b/python/src/wslink/websocket.py index 06414dc4..179aed94 100644 --- a/python/src/wslink/websocket.py +++ b/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