Merge pull request #6 from leplatrem/add-mozlog

Log every request with MozLog

Author: bsieber-mozilla

poetry.lock

@@ -14,6 +14,7 @@ gunicorn = "^20.1.0"
 prometheus-client = "^0.13.1"
 python-bugzilla = "^3.2.0"
 atlassian-python-api = "^3.20.1"
+dockerflow = "2022.1.0"
 
 [tool.poetry.dev-dependencies]
 pre-commit = "^2.17.0"

pyproject.toml

@@ -1,11 +1,18 @@
+import logging
+import time
+from datetime import datetime
+
 import uvicorn  # type: ignore
 from fastapi import FastAPI, Request
 from fastapi.responses import RedirectResponse
 
 from src.app.environment import get_settings
+from src.app.log import configure_logging
 from src.app.monitor import api_router as monitor_router
 from src.jbi.router import api_router as jbi_router
 
+settings = get_settings()
+
 app = FastAPI(
     title="Jira Bugzilla Integration (JBI)",
     description="JBI v2 Platform",
@@ -26,8 +33,38 @@ def root(request: Request):
     return RedirectResponse(url="./docs")
 
 
+@app.middleware("http")
+async def request_summary(request: Request, call_next):
+    summary_logger = logging.getLogger("request.summary")
+    previous_time = time.time()
+
+    infos = {
+        "agent": request.headers.get("User-Agent"),
+        "path": request.url.path,
+        "method": request.method,
+        "lang": request.headers.get("Accept-Language"),
+        "querystring": dict(request.query_params),
+        "errno": 0,
+    }
+
+    response = await call_next(request)
+
+    current = time.time()
+    duration = int((current - previous_time) * 1000.0)
+    isotimestamp = datetime.fromtimestamp(current).isoformat()
+    infos = {"time": isotimestamp, "code": response.status_code, "t": duration, **infos}
+
+    summary_logger.info("", extra=infos)
+
+    return response
+
+
+@app.on_event("startup")
+def startup_event():
+    configure_logging()
+
+
 if __name__ == "__main__":
-    settings = get_settings()
     uvicorn.run(
-        "app:app", host="0.0.0.0", port=settings.port, reload=settings.app_reload
+        "app:app", host=settings.host, port=settings.port, reload=settings.app_reload
     )

src/app/api.py

@@ -6,6 +6,7 @@
 
 
 class Settings(BaseSettings):
+    host: str = "0.0.0.0"
     port: str = "80"
     app_reload: bool = True
 
@@ -20,6 +21,9 @@ class Settings(BaseSettings):
     jira_password: str
     bugzilla_api_key: str
 
+    # Logging
+    log_level: str = "info"
+
 
 @lru_cache()
 def get_settings() -> Settings:

src/app/environment.py

@@ -0,0 +1,32 @@
+import logging
+import logging.config
+import sys
+
+from src.app.environment import get_settings
+
+settings = get_settings()
+
+
+def configure_logging():
+    logging_config = {
+        "version": 1,
+        "formatters": {
+            "mozlog_json": {
+                "()": "dockerflow.logging.JsonLogFormatter",
+                "logger_name": "jbi",
+            },
+        },
+        "handlers": {
+            "console": {
+                "level": settings.log_level.upper(),
+                "class": "logging.StreamHandler",
+                "formatter": "mozlog_json",
+                "stream": sys.stdout,
+            }
+        },
+        "loggers": {
+            "request.summary": {"handlers": ["console"], "level": "INFO"},
+        },
+    }
+
+    logging.config.dictConfig(logging_config)

src/app/log.py

@@ -1,3 +1,8 @@
+from fastapi.testclient import TestClient
+
+from src.app.api import app
+
+
 def test_read_root(anon_client):
     """The site root redirects to the Swagger docs"""
     resp = anon_client.get("/")
@@ -6,3 +11,16 @@ def test_read_root(anon_client):
     prev_resp = resp.history[0]
     assert prev_resp.status_code == 307  # Temporary Redirect
     assert prev_resp.headers["location"] == "./docs"
+
+
+def test_request_summary_is_logged(caplog):
+    with TestClient(app) as anon_client:
+        # https://fastapi.tiangolo.com/advanced/testing-events/
+        anon_client.get("/__lbheartbeat__")
+
+        summary = caplog.records[-1]
+
+        assert summary.name == "request.summary"
+        assert summary.method == "GET"
+        assert summary.path == "/__lbheartbeat__"
+        assert summary.querystring == {}