Tweak logging (log 500 requests), other logging-adjacent tweaks (#161)

* Set enum for acceptable environment values

* Turn app reload off by default

* Add environment variable to controll FastAPI debug mode

* Add asgi.py module at project root to run app

* Handle 500s in request summary exception handler
- use new function to format fields

* Refactor logging config
- use mozlog format for root handler
- disable uvicorn access logs
- pass config dict to Uvicorn Config

Author: grahamalama

.env.example

@@ -1,6 +1,7 @@
 # Environment variables for the local development environment
-
 ENV=local
+APP_RELOAD=True
+APP_DEBUG=True
 
 # Jira API Secrets
 JIRA_USERNAME="fake_jira_username"

.secrets.baseline

@@ -106,14 +106,14 @@
         "filename": ".env.example",
         "hashed_secret": "4b9a4ce92b6a01a4cd6ee1672d31c043f2ae79ab",
         "is_verified": false,
-        "line_number": 7
+        "line_number": 8
       },
       {
         "type": "Secret Keyword",
         "filename": ".env.example",
         "hashed_secret": "77ea6398f252999314d609a708842a49fc43e055",
         "is_verified": false,
-        "line_number": 10
+        "line_number": 11
       }
     ],
     "README.md": [
@@ -126,5 +126,5 @@
       }
     ]
   },
-  "generated_at": "2022-07-21T13:06:53Z"
+  "generated_at": "2022-07-28T11:58:31Z"
 }

Makefile

@@ -56,7 +56,7 @@ lint: $(INSTALL_STAMP)
 
 .PHONY: start
 start: $(INSTALL_STAMP) $(DOTENV_FILE)
-	poetry run python -m src.app.api
+	poetry run python -m asgi
 
 $(DOTENV_FILE):
 	cp .env.example $(DOTENV_FILE)

asgi.py

@@ -0,0 +1,19 @@
+import uvicorn
+
+from src.app.environment import get_settings
+from src.app.log import CONFIG as LOGGING_CONFIG
+
+settings = get_settings()
+
+
+if __name__ == "__main__":
+    server = uvicorn.Server(
+        uvicorn.Config(
+            "src.app.api:app",
+            host=settings.host,
+            port=settings.port,
+            reload=settings.app_reload,
+            log_config=LOGGING_CONFIG,
+        )
+    )
+    server.run()

docker-compose.yaml

@@ -2,7 +2,7 @@ version: "3.8"
 services:
   web:
     build: .
-    command: python -m src.app.api
+    command: python -m asgi
     env_file:
       - .env
     # Let the init system handle signals for us.

src/app/api.py

@@ -8,7 +8,6 @@
 from typing import Dict, List, Optional
 
 import sentry_sdk
-import uvicorn  # type: ignore
 from fastapi import Body, Depends, FastAPI, Request
 from fastapi.encoders import jsonable_encoder
 from fastapi.responses import HTMLResponse
@@ -18,7 +17,6 @@
 
 from src.app import configuration
 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.bugzilla import BugzillaWebhookRequest
 from src.jbi.models import Actions
@@ -31,12 +29,11 @@
 
 settings = get_settings()
 
-configure_logging()
-
 app = FastAPI(
     title="Jira Bugzilla Integration (JBI)",
     description="JBI v2 Platform",
     version="3.0.3",
+    debug=settings.app_debug,
 )
 
 app.include_router(monitor_router)
@@ -48,6 +45,42 @@
 app.add_middleware(SentryAsgiMiddleware)
 
 
+def format_log_fields(request: Request, request_time: float, status_code: int) -> Dict:
+    """Prepare Fields for Mozlog request summary"""
+
+    current_time = time.time()
+    fields = {
+        "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,
+        "t": int((current_time - request_time) * 1000.0),
+        "time": datetime.fromtimestamp(current_time).isoformat(),
+        "status_code": status_code,
+    }
+    return fields
+
+
+@app.middleware("http")
+async def request_summary(request: Request, call_next):
+    """Middleware to log request info"""
+    summary_logger = logging.getLogger("request.summary")
+    request_time = time.time()
+    try:
+        response = await call_next(request)
+        log_fields = format_log_fields(
+            request, request_time, status_code=response.status_code
+        )
+        summary_logger.info("", extra=log_fields)
+        return response
+    except Exception as exc:
+        log_fields = format_log_fields(request, request_time, status_code=500)
+        summary_logger.info(exc, extra=log_fields)
+        raise
+
+
 @app.get("/", include_in_schema=False)
 def root():
     """Expose key configuration"""
@@ -63,33 +96,6 @@ def root():
     }
 
 
-@app.middleware("http")
-async def request_summary(request: Request, call_next):
-    """Middleware to log request info"""
-    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.post("/bugzilla_webhook")
 def bugzilla_webhook(
     request: BugzillaWebhookRequest = Body(..., embed=False),
@@ -135,13 +141,3 @@ def powered_by_jbi(
         "enable_query": enabled,
     }
     return templates.TemplateResponse("powered_by_template.html", context)
-
-
-if __name__ == "__main__":
-    uvicorn.run(
-        "src.app.api:app",
-        host=settings.host,
-        port=settings.port,
-        reload=settings.app_reload,
-        log_level=settings.log_level,
-    )

src/app/environment.py

@@ -2,13 +2,22 @@
 Module dedicated to interacting with the environment (variables, version.json)
 """
 import json
+from enum import Enum
 from functools import lru_cache
 from pathlib import Path
 from typing import Optional
 
 from pydantic import AnyUrl, BaseSettings
 
 
+class Environment(str, Enum):
+    """Production environment choices"""
+
+    LOCAL = "local"
+    NONPROD = "nonprod"
+    PRODUCTION = "production"
+
+
 class SentryDsn(AnyUrl):
     """Url type to validate Sentry DSN"""
 
@@ -18,9 +27,10 @@ class Settings(BaseSettings):
 
     host: str = "0.0.0.0"
     port: int = 8000
-    app_reload: bool = True
-    env: str = "nonprod"
+    app_reload: bool = False
+    app_debug: bool = False
     max_retries: int = 3
+    env: Environment = Environment.NONPROD
 
     # Jira
     jira_base_url: str = "https://mozit-test.atlassian.net/"

src/app/log.py

@@ -9,30 +9,31 @@
 
 settings = get_settings()
 
-
-def configure_logging():
-    """Configure logging; mozlog format for Dockerflow"""
-    logging_config = {
-        "version": 1,
-        "formatters": {
-            "mozlog_json": {
-                "()": "dockerflow.logging.JsonLogFormatter",
-                "logger_name": "jbi",
-            },
+CONFIG = {
+    "version": 1,
+    "disable_existing_loggers": False,
+    "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,
-            }
+    },
+    "handlers": {
+        "console": {
+            "level": settings.log_level.upper(),
+            "class": "logging.StreamHandler",
+            "formatter": "mozlog_json",
+            "stream": sys.stdout,
         },
-        "loggers": {
-            "request.summary": {"handlers": ["console"], "level": "INFO"},
-            "backoff": {"handlers": ["console"], "level": "INFO"},
-            "src.jbi": {"handlers": ["console"], "level": "DEBUG"},
+        "null": {
+            "class": "logging.NullHandler",
         },
-    }
-
-    logging.config.dictConfig(logging_config)
+    },
+    "loggers": {
+        "": {"handlers": ["console"]},
+        "request.summary": {"level": logging.INFO},
+        "src": {"level": logging.DEBUG},
+        "uvicorn": {"level": logging.INFO},
+        "uvicorn.access": {"handlers": ["null"], "propagate": False},
+    },
+}

tests/unit/app/test_api.py

@@ -1,6 +1,7 @@
 """
 Module for testing src/app/api.py
 """
+import logging
 from datetime import datetime
 
 # pylint: disable=cannot-enumerate-pytest-fixtures
@@ -36,16 +37,17 @@ def test_read_root(anon_client):
 
 
 def test_request_summary_is_logged(caplog):
-    with TestClient(app) as anon_client:
-        # https://fastapi.tiangolo.com/advanced/testing-events/
-        anon_client.get("/__lbheartbeat__")
+    with caplog.at_level(logging.INFO):
+        with TestClient(app) as anon_client:
+            # https://fastapi.tiangolo.com/advanced/testing-events/
+            anon_client.get("/__lbheartbeat__")
 
-        summary = caplog.records[-1]
+            summary = caplog.records[-1]
 
-        assert summary.name == "request.summary"
-        assert summary.method == "GET"
-        assert summary.path == "/__lbheartbeat__"
-        assert summary.querystring == {}
+            assert summary.name == "request.summary"
+            assert summary.method == "GET"
+            assert summary.path == "/__lbheartbeat__"
+            assert summary.querystring == {}
 
 
 def test_whiteboard_tags(anon_client):

tests/unit/jbi/test_runner.py

@@ -1,6 +1,8 @@
 """
 Module for testing src/jbi/runner.py
 """
+import logging
+
 # pylint: disable=cannot-enumerate-pytest-fixtures
 from unittest import mock
 
@@ -89,11 +91,12 @@ def test_execution_logging_for_successful_requests(
     actions_example: Actions,
     settings: Settings,
 ):
-    execute_action(
-        request=webhook_create_example,
-        actions=actions_example,
-        settings=settings,
-    )
+    with caplog.at_level(logging.DEBUG):
+        execute_action(
+            request=webhook_create_example,
+            actions=actions_example,
+            settings=settings,
+        )
 
     captured_log_msgs = [
         r.msg % r.args for r in caplog.records if r.name == "src.jbi.runner"
@@ -114,13 +117,13 @@ def test_execution_logging_for_ignored_requests(
 ):
     assert webhook_create_example.bug
     webhook_create_example.bug.whiteboard = "foo"
-
-    with pytest.raises(IgnoreInvalidRequestError):
-        execute_action(
-            request=webhook_create_example,
-            actions=actions_example,
-            settings=settings,
-        )
+    with caplog.at_level(logging.DEBUG):
+        with pytest.raises(IgnoreInvalidRequestError):
+            execute_action(
+                request=webhook_create_example,
+                actions=actions_example,
+                settings=settings,
+            )
 
     captured_log_msgs = [
         r.msg % r.args for r in caplog.records if r.name == "src.jbi.runner"