Kludex / asgi-logger

Access logger for ASGI servers! :tada:
MIT License
48 stars 8 forks source link

Root path is duplicated in logs since starlette 0.33 #44

Open chbndrhnns opened 8 months ago

chbndrhnns commented 8 months ago

I expect the configured root path to appear only once in the logs but they do appear twice since starlette 0.33 and this change.

Starlette <0.33:

async def test_old_starlette(caplog):
    from starlette.applications import Starlette
    from starlette.middleware import Middleware
    from starlette.testclient import TestClient
    from starlette.responses import PlainTextResponse

    async def do(request):
        _ = request
        return PlainTextResponse('Hello, world!')

    from starlette.routing import Route
    routes = [Route("/do", do)]

    app = Starlette(routes=routes, middleware=[Middleware(AccessLoggerMiddleware)])

    with TestClient(app=app, root_path="/v2") as client:
        res = client.get("/do")
    assert res.status_code == 200
    messages = [record.msg % record.args for record in caplog.records]
    assert shlex.split(messages[-1]) == [Match(), "-", "GET /v2/do HTTP/1.1", "200", "OK"]

Starlette >= 0.33

async def test_new_starlette(caplog):
    from starlette.applications import Starlette
    from starlette.middleware import Middleware
    from starlette.testclient import TestClient
    from starlette.responses import PlainTextResponse

    async def do(request):
        _ = request
        return PlainTextResponse('Hello, world!')

    from starlette.routing import Route
    routes = [Route("/do", do)]

    app = Starlette(routes=routes, middleware=[Middleware(AccessLoggerMiddleware)])

    with TestClient(app=app, root_path="/v2") as client:
        res = client.get("/v2/do")
    assert res.status_code == 200
    messages = [record.msg % record.args for record in caplog.records]
    assert shlex.split(messages[-1]) == [Match(), "-", "GET /v2/do HTTP/1.1", "200", "OK"]
Output:

E       AssertionError: assert ['-', '-', 'GET /v2/v2/do HTTP/1.1', '200', 'OK'] == [<tests.unit.juice_server.test_asgi_logger.Match object at 0x11368ae80>, '-', 'GET /v2/do HTTP/1.1', '200', 'OK']
E         At index 2 diff: 'GET /v2/v2/do HTTP/1.1' != 'GET /v2/do HTTP/1.1'
E         Full diff:
E           [
E         -  <tests.unit.juice_server.test_asgi_logger.Match object at 0x11368ae80>,
E            '-',
E         +  '-',
E         -  'GET /v2/do HTTP/1.1',
E         +  'GET /v2/v2/do HTTP/1.1',
E         ?       +++
E            '200',
E            'OK',
E           ]