add a request ID for all logs generated during request handling

requirements-test.txt

@@ -12,8 +12,8 @@ chardet==3.0.4            # via aiohttp
 coverage==5.0.3           # via pytest-cov
 idna-ssl==1.1.0           # via aiohttp
 idna==2.8                 # via idna-ssl, yarl
-importlib-metadata==1.4.0  # via pluggy, pytest
-more-itertools==8.1.0     # via pytest
+importlib-metadata==1.5.0  # via pluggy, pytest
+more-itertools==8.2.0     # via pytest
 multidict==4.7.4          # via aiohttp, yarl
 packaging==20.1           # via pytest
 pluggy==0.13.1            # via pytest
@@ -22,7 +22,7 @@ pyparsing==2.4.6          # via packaging
 pytest-asyncio==0.10.0
 pytest-cov==2.8.1
 pytest-mock==2.0.0
-pytest==5.3.4
+pytest==5.3.5
 six==1.14.0               # via packaging
 typing-extensions==3.7.4.1  # via aiohttp
 wcwidth==0.1.8            # via pytest

requirements.txt

@@ -16,7 +16,7 @@ grpcio==1.26.0
 h11==0.8.1                # via httpx
 h2==3.1.1                 # via httpx
 hpack==3.0.0              # via h2
-hstspreload==2020.1.22    # via httpx
+hstspreload==2020.1.30    # via httpx
 httptools==0.0.13         # via sanic
 httpx==0.9.3              # via sanic
 hyperframe==5.2.0         # via h2
@@ -36,6 +36,7 @@ requests==2.22.0          # via kubernetes, requests-oauthlib
 rfc3986==1.3.2            # via httpx
 rsa==4.0                  # via google-auth
 sanic==19.12.2
+shortuuid==0.5.0
 six==1.14.0               # via google-auth, grpcio, kubernetes, protobuf, python-dateutil, structlog, websocket-client
 sniffio==1.1.0            # via httpx
 structlog==20.1.0

setup.py

@@ -48,7 +48,8 @@
         'pyyaml>=4.2b1',
         'sanic>=0.8.0',
         'prometheus-client',
-        'structlog',
+        'shortuuid',
+        'structlog>=20.1.0',
         'websockets',
         'synse-grpc==3.0.0a4',  # fixme: for alpha v3 testing; update to stable v3 release
     ],

synse_server/app.py

@@ -1,10 +1,17 @@
 """Factory for creating Synse Server Sanic application instances."""
 
+import shortuuid
+import structlog
 from sanic import Sanic
+from sanic.request import Request
+from sanic.response import HTTPResponse
+from structlog import contextvars
 
 from synse_server import errors
 from synse_server.api import http, websocket
 
+logger = structlog.get_logger()
+
 
 def new_app() -> Sanic:
     """Create a new instance of the Synse Server Sanic application.
@@ -31,4 +38,29 @@ def new_app() -> Sanic:
     # a browser hits an endpoint and can't find the icon.
     app.static('/favicon.ico', '/etc/synse/static/favicon.ico')
 
+    # Register middleware with the application.
+    app.register_middleware(on_request, 'request')
+    app.register_middleware(on_response, 'response')
+
     return app
+
+
+def on_request(request: Request) -> None:
+    """Middleware function that runs prior to processing a request via Sanic."""
+    # Generate a unique request ID and use it as a field in any logging that
+    # takes place during the request handling.
+    req_id = shortuuid.uuid()
+    request.ctx.uuid = req_id
+
+    contextvars.clear_contextvars()
+    contextvars.bind_contextvars(
+        request_id=req_id,
+    )
+
+
+def on_response(request: Request, response: HTTPResponse) -> None:
+    """Middleware function that runs prior to returning a response via Sanic."""
+    # Unbind the request ID from the logger.
+    contextvars.unbind_contextvars(
+        'request_id',
+    )

synse_server/log.py

@@ -6,6 +6,7 @@
 
 import structlog
 from sanic import app, asgi, handlers, request, server
+from structlog import contextvars
 
 from synse_server import config
 
@@ -55,6 +56,7 @@
 
 structlog.configure(
     processors=[
+        contextvars.merge_contextvars,
         structlog.stdlib.filter_by_level,
         structlog.stdlib.add_logger_name,
         structlog.stdlib.add_log_level,