improve logging

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}")
+        LOGGER.error(f"Send error: {e}")
-        logging.warning("Reconnecting and trying again")
+        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()

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

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())