Access log logs wrong status on file responses

[gaborbernat]

I noticed that 200s are logged as 500. Modified https://github.com/emmett-framework/granian/blob/master/granian/asgi.py#L109 with:

def _callback_wrapper(callback, scope_opts, state, access_log_fmt=None):
    root_url_path = scope_opts.get("url_path_prefix") or ""

    def _runner(scope, proto):
        scope.update(root_path=root_url_path, state=state.copy())
        return callback(scope, proto.receive, proto.send)

    async def _http_logger(scope, proto):
        t = time.time()
        try:
            rv = await _runner(scope, proto)
        finally:
            interval = 0.0001
            for i in range(5):
                print(f"{interval * i} code: {proto.sent_response_code}")
                time.sleep(interval)
            access_log(t, scope, proto.sent_response_code)
        return rv

    def _logger(scope, proto):
        if scope["type"] == "http":
            return _http_logger(scope, proto)
        return _runner(scope, proto)

    access_log = _build_access_logger(access_log_fmt)
    wrapper = _logger if access_log_fmt else _runner
    wraps(callback)(wrapper)

    return wrapper

Output:

2024-07-08 09:39:14.214-0700 13785 INFO _granian.asgi.serve Started worker-2
2024-07-08 09:39:14.214-0700 13785 INFO _granian.asgi.serve Started worker-2 runtime-1
2024-07-08 09:39:14.280-0700 13784 INFO _granian.asgi.serve Started worker-1
2024-07-08 09:39:14.280-0700 13784 INFO _granian.asgi.serve Started worker-1 runtime-1

0.0 code: 500
0.0001 code: 500
0.0002 code: 200
0.00030000000000000003 code: 200
0.0004 code: 200

2024-07-08 09:39:17.831-0700 13784 INFO granian.access 127.0.0.1 - "GET /favicon.ico HTTP/1.1" 200 20.887
0.0 code: 500
0.0001 code: 500
0.0002 code: 200
0.00030000000000000003 code: 200
0.0004 code: 200

2024-07-08 09:39:18.499-0700 13784 INFO granian.access 127.0.0.1 - "GET /favicon.ico HTTP/1.1" 200 3.204
0.0 code: 500
0.0001 code: 500
0.0002 code: 200
0.00030000000000000003 code: 200
0.0004 code: 200

As you can see, the access log is logged before the response is sent, and I assume 500 is the default value.

The response type in question is a FileResponse from starlette. When I remove my for loop, the status code logged is always 500.

[gi0baro]

This is confirmed, and it happens on ASGI pathsend responses and RSGI response_file responses. The issues is caused by the fact Granian won't block the Python application for file opening and reading; and just making the app waiting for that looks very sub-optimal to me. Will think about a solution for this in the following days.

[gaborbernat]

Are you going to EuroPython by any chance? :D

[gi0baro]

Are you going to EuroPython by any chance? :D

Nope, unfortunately this year I won't be able to attend :(

[gaborbernat]

This is confirmed, and it happens on ASGI pathsend responses and RSGI response_file responses. The issues is caused by the fact Granian won't block the Python application for file opening and reading; and just making the app waiting for that looks very sub-optimal to me. Will think about a solution for this in the following days.

Hardcode response to 200 if the file exists? 😆 Though would not handle not changed responses...

[gi0baro]

So, I pushed 72a9a21 that won't fix the actual issue, but at least prevents fake 500 status codes in access logs. This means next revision will report 200 even if Granian is not able to open the file (and thus the real response code will be 404).

I'll keep this opened until I find a proper fix.