From a0a78bbad097a36101d205bf7588758ab00a9832 Mon Sep 17 00:00:00 2001 From: Guilhem Saurel Date: Wed, 14 Jul 2021 20:00:52 +0200 Subject: [PATCH] improve logging --- matrix_webhook.py | 22 ++++++++++++---------- tests/Dockerfile | 2 +- tests/start.py | 20 +++++++++++++++++++- 3 files changed, 32 insertions(+), 12 deletions(-) diff --git a/matrix_webhook.py b/matrix_webhook.py index f754680..c52fe43 100755 --- a/matrix_webhook.py +++ b/matrix_webhook.py @@ -73,7 +73,6 @@ parser.add_argument( ) args = parser.parse_args() -logging.basicConfig(level=50 - 10 * args.verbose) SERVER_ADDRESS = (args.host, args.port) MATRIX_URL = args.matrix_url @@ -81,6 +80,7 @@ MATRIX_ID = args.matrix_id MATRIX_PW = args.matrix_pw API_KEY = args.api_key CLIENT = AsyncClient(args.matrix_url, args.matrix_id) +LOGGER = logging.getLogger("matrix-webhook") async def handler(request): @@ -89,7 +89,7 @@ async def handler(request): This one handles a POST, checks its content, and forwards it to the matrix room. """ - logging.debug(f"Handling {request=}") + LOGGER.debug(f"Handling {request=}") data = await request.read() try: @@ -115,8 +115,8 @@ async def handler(request): try: await send_room_message(room_id, content) except LocalProtocolError as e: # Connection lost, try another login - logging.error(f"Send error: {e}") - logging.warning("Reconnecting and trying again") + LOGGER.error(f"Send error: {e}") + LOGGER.warning("Reconnecting and trying again") await CLIENT.login(MATRIX_PW) await send_room_message(room_id, content) @@ -125,14 +125,14 @@ async def handler(request): def create_json_response(status, ret): """Create a JSON response.""" - logging.debug(f"Creating json response: {status=}, {ret=}") + LOGGER.debug(f"Creating json response: {status=}, {ret=}") response_data = {"status": status, "ret": ret} return web.json_response(response_data, status=status) async def send_room_message(room_id, content): """Send a message to a room.""" - logging.debug(f"Sending room message in {room_id=}: {content=}") + LOGGER.debug(f"Sending room message in {room_id=}: {content=}") return await CLIENT.room_send( room_id=room_id, message_type="m.room.message", content=content ) @@ -144,13 +144,13 @@ async def main(event): matrix client login & start web server """ - logging.info(f"Log in {MATRIX_ID=} on {MATRIX_URL=}") + LOGGER.info(f"Log in {MATRIX_ID=} on {MATRIX_URL=}") await CLIENT.login(MATRIX_PW) server = web.Server(handler) runner = web.ServerRunner(server) await runner.setup() - logging.info(f"Binding on {SERVER_ADDRESS=}") + LOGGER.info(f"Binding on {SERVER_ADDRESS=}") site = web.TCPSite(runner, *SERVER_ADDRESS) await site.start() @@ -170,7 +170,7 @@ def terminate(event, signal): def run(): """Launch everything.""" - logging.info("Matrix Webhook starting...") + LOGGER.info("Starting...") loop = asyncio.get_event_loop() event = asyncio.Event() @@ -179,9 +179,11 @@ def run(): loop.run_until_complete(main(event)) - logging.info("Matrix Webhook closing...") + LOGGER.info("Closing...") loop.close() if __name__ == "__main__": + log_format = "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(message)s" + logging.basicConfig(level=50 - 10 * args.verbose, format=log_format) run() diff --git a/tests/Dockerfile b/tests/Dockerfile index 0ff4cb2..42b60b9 100644 --- a/tests/Dockerfile +++ b/tests/Dockerfile @@ -17,4 +17,4 @@ RUN pip install --no-cache-dir markdown matrix-nio httpx coverage WORKDIR /app -CMD ./tests/start.py +CMD ./tests/start.py -vvv diff --git a/tests/start.py b/tests/start.py index 27c184c..3124927 100755 --- a/tests/start.py +++ b/tests/start.py @@ -1,6 +1,8 @@ #!/usr/bin/env python """Entry point to start an instrumentalized bot for coverage and run tests.""" +import argparse +import logging from os import environ from subprocess import Popen, run from time import time @@ -15,6 +17,12 @@ KEY, MATRIX_URL, MATRIX_ID, MATRIX_PW = ( environ[v] for v in ["API_KEY", "MATRIX_URL", "MATRIX_ID", "MATRIX_PW"] ) FULL_ID = f'@{MATRIX_ID}:{MATRIX_URL.split("/")[2]}' +LOGGER = logging.getLogger("matrix-webhook.tests.start") + +parser = argparse.ArgumentParser(description=__doc__) +parser.add_argument( + "-v", "--verbose", action="count", default=0, help="increment verbosity level" +) def bot_req(req=None, key=None, room_id=None): @@ -47,6 +55,7 @@ def wait_available(url: str, key: str, timeout: int = 10) -> bool: def run_and_test(): """Launch the bot and its tests.""" # Start the server, and wait for it + LOGGER.info("Spawning synapse") srv = Popen( [ "python", @@ -60,29 +69,38 @@ def run_and_test(): return False # Register a user for the bot. + LOGGER.info("Registering the bot") with open("/srv/homeserver.yaml") as f: secret = yaml.safe_load(f.read()).get("registration_shared_secret", None) request_registration(MATRIX_ID, MATRIX_PW, MATRIX_URL, secret, admin=True) # Start the bot, and wait for it - bot = Popen(["coverage", "run", "matrix_webhook.py"]) + LOGGER.info("Spawning the bot") + bot = Popen(["coverage", "run", "matrix_webhook.py", "-vvvvv"]) if not wait_available(BOT_URL, "status"): return False # Run the main unittest module + LOGGER.info("Runnig unittests") ret = main(module=None, exit=False).result.wasSuccessful() + LOGGER.info("Stopping synapse") srv.terminate() # TODO Check what the bot says when the server is offline # print(bot_req({'text': 'bye'}, KEY), {'status': 200, 'ret': 'OK'}) + LOGGER.info("Stopping the bot") bot.terminate() + LOGGER.info("Processing coverage") for cmd in ["report", "html", "xml"]: run(["coverage", cmd]) return ret if __name__ == "__main__": + args = parser.parse_args() + log_format = "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(message)s" + logging.basicConfig(level=50 - 10 * args.verbose, format=log_format) exit(not run_and_test())