hypercorn
hypercorn copied to clipboard
pgjones
Access logs looks duplicated
When running an application, it looks like access logs are always duplicated. The first access log on request is fine and show all required information. Then there is a completely identical log right after with only a small difference, it does not have any status code nor size (got - instead).
Note that I tried to change settings, log configuration and so on without any success
$ hypercorn --access-log '-' main:app
[2023-11-21 10:17:51 +0100] [15956] [WARNING] ASGI Framework Lifespan error, continuing without
Lifespan support
[2023-11-21 10:17:51 +0100] [15956] [INFO] Running on http://127.0.0.1:8000 (CTRL + C to quit)
[2023-11-21 10:17:54 +0100] [15956] [INFO] 127.0.0.1:64983 - - [21/Nov/2023:10:17:54 +0100] "GET / 1.1" 200 5 "-" "curl/7.80.0"
[2023-11-21 10:17:54 +0100] [15956] [INFO] 127.0.0.1:64983 - - [21/Nov/2023:10:17:54 +0100] "GET / 1.1" - - "-" "curl/7.80.0"
Python
3.10Microsoft Windows 10 Enterprise (and gitbash) Hypercorn0.15.0
Expected behavior
I would personally expect to have a single access log per request. However, maybe I'm wrong and I missed the point of that second log message. In the latter, is there a way to disable it?
How to reproduce
- Install fastapi and hypercorn
python -m venv .venv
source .venv/bin/activate
pip install 'hypercorn==0.15.0'
- Create small api (using the one given in tutorial)
sync def app(scope, receive, send):
if scope["type"] != "http":
raise Exception("Only the HTTP protocol is supported")
await send(
{
"type": "http.response.start",
"status": 200,
"headers": [
(b"content-type", b"text/plain"),
(b"content-length", b"5"),
],
}
)
await send(
{
"type": "http.response.body",
"body": b"hello",
}
)
- Run a request
curl http://localhost:8000
Cheers!
Bit of a rabbit hole, but I figured out why. Kinda looks like intended behavior, or maybe an unforeseen consequence of intended behavior, at least.
The clue was in the difference between the two logs. The first one has the status and the response length, and the second, doesn't. If you look at the hypercorn.logging.Logger class, it has a special method to log access, which accept both a request and a response object. The status and response length are, of course, extracted from the response:
...
async def access(
self, request: "WWWScope", response: "ResponseSummary", request_time: float
) -> None:
if self.access_logger is not None:
self.access_logger.info(
self.access_log_format, self.atoms(request, response, request_time)
)
...
So I went chasing where hypercorn.logging.Logger.access is called. Turns out it's called a couple of times in hypercorn.protocol.http_stream.HTTPStream.
When the event being handled by the handle method is a a Request, it will call app_send, which will eventually call hypercorn.logging.Logger.access, before closing the connection, here:
...
if not message.get("more_body", False):
if self.state != ASGIHTTPState.CLOSED:
self.state = ASGIHTTPState.CLOSED
await self.config.log.access(
self.scope, self.response, time() - self.start_time
)
await self.send(EndBody(stream_id=self.stream_id))
await self.send(StreamClosed(stream_id=self.stream_id))
...
However, if the event is StreamClosed, it will also call hypercorn.logging.Logger.access, but pass the response as None (ref):
...
elif isinstance(event, StreamClosed):
self.closed = True
await self.config.log.access(self.scope, None, time() - self.start_time)
if self.app_put is not None:
await self.app_put({"type": "http.disconnect"})
...
From the previous snippet above, we can see that app_send itself is sending a StreamClosed, which will get handled by handle, triggering a second, less complete, log statement to be emitted.
So, this give us an avenue to shut up the second log: extend hypercorn.logging.Logger and override access to do nothing if response is None:
from hypercorn.logging import Logger as HypercornLogger
class QuieterLogger(HypercornLogger):
async def access(
self, request: WWWScope, response: ResponseSummary, request_time: float
) -> None:
if response is not None:
await super().access(request, response, request_time)
Than in the configuration, we set logger_class attribute to our new class, and voilà:
...
config = Config()
...
config.logger_class = QuieterLogger
asyncio.run(serve(app, config))
That's a pretty ugly workaround, though. From the commit that introduced this log statement, it looks like the goal is to log cancelled requests. Maybe the HTTPStream.handle method could check if self.state is not ASGIHTTPState.CLOSED when handling StreamClosed, which I think would be enough to identify a cancelled request? The only place where I see HTTPStream.state being set to ASGIHTTPState.CLOSED is right before logging a successful request.
Thanks you for that impressive deep dive into the code and explanation. I'm not sure I can do anything about this on my side. Thanks for the workaround by the way. I'll leave this open then.
In case you run hypercorn not programmatically but like that:
hypercorn --config hypercorn-cfg.toml my.app
and fail to specify the logger_class in the toml file, you can also monkey patch the class like that in your app.py file:
# patch logger_class used by hypercorn to avoid duplicate access log entries
hypercorn.config.Config.logger_class = SaneLogger
ugly, but worked for me
