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.