Include query_string in logs

[simonw]

Refs #382

[simonw]

I didn't see any existing unit tests for logging and I wasn't sure how best to add them.

Here's example output from my local development instance:

INFO: ('127.0.0.1', 62821) - "GET /fixtures/no_primary_key.json HTTP/1.1" 200
INFO: ('127.0.0.1', 62821) - "GET /fixtures/no_primary_key?_sort=content HTTP/1.1" 200
INFO: ('127.0.0.1', 62821) - "GET /-/static/app.css?5e037f HTTP/1.1" 200
INFO: ('127.0.0.1', 62824) - "GET /fixtures?sql=select+rowid%2C+%2A+from+no_primary_key+order+by+content+limit+101 HTTP/1.1" 200

[simonw]

I'm a little bit puzzled by these test failures:

=================================== FAILURES ===================================
_____________________________ test_invalid_format ______________________________
    def test_invalid_format():
        with pytest.raises(ImportFromStringError) as exc:
            import_from_string("example:")
        expected = 'Import string "example:" must be in format "<module>:<attribute>".'
>       assert expected in str(exc)
E       assert 'Import string "example:" must be in format "<module>:<attribute>".' in '<ExceptionInfo ImportFromStringError tblen=2>'
E        +  where '<ExceptionInfo ImportFromStringError tblen=2>' = str(<ExceptionInfo ImportFromStringError tblen=2>)
tests/importer/test_importer.py:10: AssertionError
_____________________________ test_invalid_module ______________________________
    def test_invalid_module():
        with pytest.raises(ImportFromStringError) as exc:
            import_from_string("module_does_not_exist:myattr")
        expected = 'Could not import module "module_does_not_exist".'
>       assert expected in str(exc)
E       assert 'Could not import module "module_does_not_exist".' in '<ExceptionInfo ImportFromStringError tblen=2>'
E        +  where '<ExceptionInfo ImportFromStringError tblen=2>' = str(<ExceptionInfo ImportFromStringError tblen=2>)
tests/importer/test_importer.py:17: AssertionError
______________________________ test_invalid_attr _______________________________
    def test_invalid_attr():
        with pytest.raises(ImportFromStringError) as exc:
            import_from_string("tempfile:attr_does_not_exist")
        expected = 'Attribute "attr_does_not_exist" not found in module "tempfile".'
>       assert expected in str(exc)
E       assert 'Attribute "attr_does_not_exist" not found in module "tempfile".' in '<ExceptionInfo ImportFromStringError tblen=2>'
E        +  where '<ExceptionInfo ImportFromStringError tblen=2>' = str(<ExceptionInfo ImportFromStringError tblen=2>)
tests/importer/test_importer.py:24: AssertionError

I can't replicate them in my local environment.

[simonw]

Interesting thing I spotted while building the unit test: it looks like the ASGI specification makes it impossible to tell the difference between hits to / and hits to /? - both result in the same scope. I don't think it's a problem, just interesting.

[tomchristie]

Addressing the (unrelated) test failures you're seeing here: #385

[tomchristie]

And yes - ASGI can't see the '?' (WSGI either)

If I'd have remembered that at the time I guess I might(?) have advocated for raw_path to be both the path and query string, without any parsing or modification whatsoever.

[tomchristie]

Alrighy - looks like if you merge master then those tests oughta start passing again.

[simonw]

Hmm... that fixed the previous failures but I now have this one, which is also puzzling to me:

___________________ test_request_logging[/?foo-H11Protocol] ___________________
protocol_cls = <class 'uvicorn.protocols.http.h11_impl.H11Protocol'>
path = '/?foo'
caplog = <_pytest.logging.LogCaptureFixture object at 0x0000021042B23390>
    @pytest.mark.parametrize("protocol_cls", HTTP_PROTOCOLS)
    @pytest.mark.parametrize("path", ["/", "/?foo", "/?foo=bar", "/?foo=bar&baz=1"])
    def test_request_logging(protocol_cls, path, caplog):
        get_request_with_query_string = b"\r\n".join(
            ["GET {} HTTP/1.1".format(path).encode("ascii"), b"Host: example.org", b"", b""]
        )
        caplog.set_level(logging.INFO, logger="uvicorn")
        app = Response("Hello, world", media_type="text/plain")
    
        protocol = get_connected_protocol(app, protocol_cls)
        protocol.data_received(get_request_with_query_string)
        protocol.loop.run_one()
    
>       assert '"GET {} HTTP/1.1" 200'.format(path) in caplog.records[0].message
E       assert '"GET /?foo HTTP/1.1" 200' in 'Task was destroyed but it is pending!\ntask: <Task pending coro=<WSGIResponder.sender() done, defined at C:\\Users\\t...icorn\\middleware\\wsgi.py:100> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x0000021042AC61F8>()]>>'

[tomchristie]

Strange - also it's only occurring on the windows build.
Could it be something odd to do with the interaction between the two parameterizations?
How's it run without the path parameterization decorator in place?

[tomchristie]

Or, eg. if you swap the two parameterization decorators around so that they're ordered the other way?

[tomchristie]

Or if you swap the second one so that it's only running ?foo, which is the failing case?

[simonw]

Swapping the order of the two parameterization decorators worked, great hunch there!

[simonw]

Anything else we need to do before we can merge this?

[tomchristie]

Released! 0.8.4

Thanks 🙏