Fix RemoteProtocolError: Server disconnected without sending a response.

[danielballan]

This seems to be a regression introduced by #750. I can reproduce it by raising an exception in exactly the right place in the middleware:

diff --git a/tiled/server/app.py b/tiled/server/app.py
index 1ba9dfcd..21e48e72 100644
--- a/tiled/server/app.py
+++ b/tiled/server/app.py
@@ -875,6 +875,9 @@ Back up the database, and then run:
         request.state.principal = SpecialUsers.public
         response = await call_next(request)
         response.__class__ = PatchedStreamingResponse  # tolerate memoryview
+        import random
+        if random.random() > 0.5:
+            raise Exception
         current_principal.set(request.state.principal)
         return response

[danielballan]

The change above results in a failure during logging that causes the server not to send a response. The key section is:

  File "/home/dallan/Repos/bnl/tiled/tiled/server/principal_log_filter.py", line 11, in filter
    principal = current_principal.get()
                ^^^^^^^^^^^^^^^^^^^^^^^
LookupError: <ContextVar name='current_principal' at 0x76ebe9fb89f0>

Full output expandable here:

[d767dc437ae91daa] ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
    await self.app(scope, receive, _send)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/asgi_correlation_id/middleware.py", line 90, in __call__
    await self.app(scope, receive, handle_outgoing_request)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/starlette/middleware/base.py", line 191, in __call__
    response = await self.dispatch_func(request, call_next)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/dallan/Repos/bnl/tiled/tiled/server/app.py", line 878, in current_principal_logging_filter
    raise Exception("test")
Exception: test

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 411, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 69, in __call__
    return await self.app(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/fastapi/applications.py", line 1054, in __call__
    await super().__call__(scope, receive, send)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/starlette/applications.py", line 123, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/starlette/middleware/errors.py", line 181, in __call__
    await response(scope, receive, send)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/starlette/responses.py", line 152, in __call__
    await send(
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 481, in send
    self.access_logger.info(
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/logging/__init__.py", line 1489, in info
    self._log(INFO, msg, args, **kwargs)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/logging/__init__.py", line 1634, in _log
    self.handle(record)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/logging/__init__.py", line 1644, in handle
    self.callHandlers(record)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/logging/__init__.py", line 1706, in callHandlers
    hdlr.handle(record)
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/logging/__init__.py", line 974, in handle
    rv = self.filter(record)
         ^^^^^^^^^^^^^^^^^^^
  File "/home/dallan/micromamba/envs/py311/lib/python3.11/logging/__init__.py", line 830, in filter
    result = f.filter(record)
             ^^^^^^^^^^^^^^^^
  File "/home/dallan/Repos/bnl/tiled/tiled/server/principal_log_filter.py", line 11, in filter
    principal = current_principal.get()
                ^^^^^^^^^^^^^^^^^^^^^^^
LookupError: <ContextVar name='current_principal' at 0x76ebe9fb89f0>

This fix ensures that a (500) response is sent. It's probably worth having this in place as a fail-safe, but I think we should also try to set the principal even for 500 responses if possible.

diff --git a/tiled/server/principal_log_filter.py b/tiled/server/principal_log_filter.py
index faf4f0fd..2580ea3f 100644
--- a/tiled/server/principal_log_filter.py
+++ b/tiled/server/principal_log_filter.py
@@ -8,8 +8,10 @@ class PrincipalFilter(Filter):
     """Logging filter to attach username or Service Principal UUID to LogRecord"""
 
     def filter(self, record: LogRecord) -> bool:
-        principal = current_principal.get()
-        if isinstance(principal, SpecialUsers):
+        principal = current_principal.get(None)
+        if principal is None:
+            short_name = "unset"
+        elif isinstance(principal, SpecialUsers):
             short_name = f"{principal.value}"
         elif principal.type == "service":
             short_name = f"service:{principal.uuid}"

[danielballan]

Closed by #754