[PROPOSAL] new signal on_request

[hh-h]

Long story short

We want to attach context from contextvars to logger message

Problem

When user tries to put some information to logs (i.e. request_id) there's no access to contextvars, because user can only put something to contextvars in middleware

I propose to add new signal, like response.on_prepare, but for request, where I can put something to contextvars, for example mark this request with uuid.

see example (python 3.7 only):

import logging
import uuid
from logging.config import dictConfig

import contextvars
from aiohttp import web
from aiohttp.abc import AbstractAccessLogger

REQUEST_ID = contextvars.ContextVar("request_id")

class AsyncAccessLogger(AbstractAccessLogger):
    def log(self, request, response, time):
        print(("AsyncAccessLogger", REQUEST_ID.get()))
        self.logger.info("test")

class ContextFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.__dict__.update({"request_id": REQUEST_ID.get()})
        return True

def setup_logs():
    dictConfig(
        config={
            "version": 1,
            "disable_existing_loggers": False,
            "filters": {"request_context": {"()": "start_log_test.ContextFilter"}},
            "handlers": {"stdout": {"level": "DEBUG", "class": "logging.StreamHandler"}},
            "loggers": {
                "aiohttp.access": {"handlers": ["stdout"], "level": "DEBUG"},
                "aiohttp.server": {"handlers": ["stdout"], "level": "DEBUG"},
            },
        }
    )

@web.middleware
async def request_id(request, handler):
    REQUEST_ID.set(str(uuid.uuid4()))
    return await handler(request)

async def get_(request: web.Request):
    print(("REQUEST", REQUEST_ID.get()))
    # for exception
    1 / 0
    return web.json_response()

def main():
    app = web.Application(middlewares=[request_id])
    app.add_routes([web.get("/", get_)])
    setup_logs()
    web.run_app(app, access_log_class=AsyncAccessLogger, port=8088)

if __name__ == "__main__":
    main()

after request

======== Running on http://0.0.0.0:8088 ========
(Press CTRL+C to quit)
('REQUEST', '3bd497ec-1df1-4deb-842d-d12197a9c9a1')
Error handling request
Traceback (most recent call last):
  File ".../code/venvs/aiohttp_logs/lib/python3.7/site-packages/aiohttp/web_protocol.py", line 418, in start
    resp = await task
  File ".../code/venvs/aiohttp_logs/lib/python3.7/site-packages/aiohttp/web_app.py", line 458, in _handle
    resp = await handler(request)
  File ".../code/venvs/aiohttp_logs/lib/python3.7/site-packages/aiohttp/web_middlewares.py", line 119, in impl
    return await handler(request)
  File ".../code/python/aiohttp_logs/start_log_test.py", line 42, in request_id
    return await handler(request)
  File ".../code/python/aiohttp_logs/start_log_test.py", line 48, in get_
    1 / 0
ZeroDivisionError: division by zero
Unhandled exception
Traceback (most recent call last):
  File ".../code/venvs/aiohttp_logs/lib/python3.7/site-packages/aiohttp/web_protocol.py", line 455, in start
    self.log_access(request, resp, loop.time() - now)
  File ".../code/venvs/aiohttp_logs/lib/python3.7/site-packages/aiohttp/web_protocol.py", line 348, in log_access
    self.access_logger.log(request, response, time)
  File ".../code/python/aiohttp_logs/start_log_test.py", line 14, in log
    print(("AsyncAccessLogger", REQUEST_ID.get()))
LookupError: <ContextVar name='request_id' at 0x10aee7d00>

If we agree on design/architecture, I can work on pull request or maybe someone can give us a hint how to achieve that :)

Thanks!

[asvetlov]

Sounds interesting.
What on_request signal can do? What is the callback signature?
I can imagine that a signal handler accepts a request an return a request: Callable[[web.Request], Awaitable[web.Request]].
The handler can not only modify context var but also replace passed request with a copy (request.clone()) to modify path, method etc.

But it doesn't solve your initial problem: contextvar change performed by middleware (or web-handler) is not visible by access logger.
That's because to make contextvar separation every request is executed in own task: https://github.com/aio-libs/aiohttp/blob/master/aiohttp/web_protocol.py#L414-L415
Task creates a copy of contextvar context on creation.
self.access_log is called outside of this task context.

So, regardless of adding on_request signal, we need to call access logger from the same task.
PR is welcome!

[hh-h]

Your signature makes sense to me. So as far as I understood, it is possible to implement. Regarding the link you provided, could you provide any directions? Should I move calling self.access_log somewhere or move creating new task?

[asvetlov]

I think we need extract https://github.com/aio-libs/aiohttp/blob/master/aiohttp/web_protocol.py#L414-L435 into a separate method and call the whole method inside a task.
Something like

    async def _handle_request(self, request):
                try:
                    resp = await self._request_handler(request)
                except HTTPException as exc:
                    resp = Response(status=exc.status,
                                    reason=exc.reason,
                                    text=exc.text,
                                    headers=exc.headers)
                    return await self.finish_response(request, resp, start)
                except asyncio.CancelledError:
                    raise
                except asyncio.TimeoutError as exc:
                    self.log_debug('Request handler timed out.', exc_info=exc)
                    resp = self.handle_error(request, 504)
                    return await self.finish_response(request, resp, start)
                except Exception as exc:
                    resp = self.handle_error(request, 500, exc)
                    return await self.finish_response(request, resp, start)
                else:
                    return await self.finish_response(request, resp, start)

    async def start(self) -> None:
           ...
            try:
                # a new task is used for copy context vars (#3406)
                task = self._loop.create_task(
                    self._handle_request(request))
                try:
                    reset = await task
                except asyncio.CancelledError:
                    self.log_debug('Ignored premature client disconnection')
                    break
                # Drop the processed task from asyncio.Task.all_tasks() early
                del task
                if reset:
                    self.log_debug('Ignored premature client disconnection 2')
                    break
            ...

The PR should not add on_request signal, it is self-contained. A new signal requires a separate PR.

[asvetlov]

Fixed by #3804