Repository: encode/httpx

Issue:
Logging levels
I've been spending some time looking at logging levels with `uvicorn` lately, see eg. https://github.com/encode/uvicorn/pull/474 and would like to take a consistent approach across other projects in `encode`.

We've currently got some very detailed logging, that's available, tho it's really at a "dig into the internals" level, rather than general purpose log outputs.

Something that would tie in really nicely with the approach I'm taking elsewhere would be to have DEBUG-level outputs that issue a single line per-request...

`[DEBUG] HTTP Request: "GET https://api.github.com/user HTTP/1.1" 200 OK`

And then have a `TRACE` level outputs reserved for the really low-level stuff.

Discussion:
tomchristie: Great stuff! Welcome to open an issue on unicorn wrt. logger names etc.
Thought: Ideally we’d probably want log all requests in any redirect chain, right?
florimondmanca: > Thought: Ideally we’d probably want log all requests in any redirect chain, right?

Think so, and I think this PR already supports this. I’ll need to check, but my thinking is that the redirect functionality calls get_response() on repeat for each redirect step, so it should work. :)
florimondmanca: @tomchristie I added some tests for the logging behavior on redirect. I reckon this PR now does a bunch of different things, so I opened https://github.com/encode/httpx/pull/506 which should get merged first, and then we can get this in. :+1:
tomchristie: A thought on formats:

Right now we've got...

* `HTTP Request:  "GET https://www.google.com HTTP/2" 200 OK`

We're indicating something *like* the request line in the quotes, except that it's not quite the actual HTTP request line, since it has the complete URL, and the HTTP version comes from the response. (I *guess* it'll always be the same at the moment, but if we supported `Upgrade` then the request line would indicate HTTP/1.1, and the response line would indicate HTTP/2)

Something we *could* do instead would be to log the literal *response line* instead, so...

* `HTTP Request:  GET https://www.google.com "HTTP/2 200 OK"`

This then has a kind of nice symmetry, in that server logs output a literal request line, and client logs output a literal response line.

Maybe?
florimondmanca: @tomchristie I like that, yep!
florimondmanca: @tomchristie Should be ready for re-review. :-)

Patch:
diff --git a/docs/environment_variables.md b/docs/environment_variables.md
index 74c2243..15723fb 100644
--- a/docs/environment_variables.md
+++ b/docs/environment_variables.md
@@ -16,9 +16,9 @@ and what function they serve:
 
 Valid values: `debug`, `trace` (case-insensitive)
 
-If set to `trace`, then low-level details about the execution of HTTP requests will be logged to `stderr`. This can help you debug issues and see what's exactly being sent over the wire and to which location.
+If set to `debug`, then HTTP requests will be logged to `stderr`. This is useful for general purpose reporting of network activity.
 
-The `debug` log level is currently ignored, but is planned to issue high-level logs of HTTP requests.
+If set to `trace`, then low-level details about the execution of HTTP requests will be logged to `stderr`, in addition to debug log lines. This can help you debug issues and see what's exactly being sent over the wire and to which location.
 
 Example:
 
@@ -30,23 +30,50 @@ with httpx.Client() as client:
     r = client.get("https://google.com")
 ```
 
+Debug output:
+
+```console
+$ HTTPX_LOG_LEVEL=debug python test_script.py
+DEBUG [2019-11-06 19:11:24] httpx.client - HTTP Request: GET https://google.com "HTTP/1.1 301 Moved Permanently"
+DEBUG [2019-11-06 19:11:24] httpx.client - HTTP Request: GET https://www.google.com/ "HTTP/1.1 200 OK"
+```
+
+Trace output:
+
 ```console
-user@host:~$ HTTPX_LOG_LEVEL=trace python test_script.py
-20:54:17.585 - httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.google.com' port=443)
-20:54:17.585 - httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
-20:54:17.590 - httpx.dispatch.connection - start_connect host='www.google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
-20:54:17.651 - httpx.dispatch.connection - connected http_version='HTTP/2'
-20:54:17.651 - httpx.dispatch.http2 - send_headers stream_id=1 headers=[(b':method', b'GET'), (b':authority', b'www.google.com'), ...]
-20:54:17.652 - httpx.dispatch.http2 - end_stream stream_id=1
-20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event=<RemoteSettingsChanged changed_settings:{...}>
-20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
-20:54:17.682 - httpx.dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
-20:54:17.739 - httpx.dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'200'), ...]>
-20:54:17.741 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:5224 data:>
-20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:59, data:>
-20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
-20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
-20:54:17.743 - httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
+$ HTTPX_LOG_LEVEL=trace python test_script.py
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='google.com' port=443)
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='google.com' port=443))
+TRACE [2019-11-06 19:18:56] httpx.config - load_ssl_context verify=True cert=None trust_env=True http_versions=HTTPVersionConfig(['HTTP/1.1', 'HTTP/2'])
+TRACE [2019-11-06 19:18:56] httpx.config - load_verify_locations cafile=/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/certifi/cacert.pem
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection - start_connect host='google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection - connected http_version='HTTP/2'
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - send_headers stream_id=1 method='GET' target='/' headers=[(b':method', b'GET'), (b':authority', b'google.com'), (b':scheme', b'https'), (b':path', b'/'), (b'user-agent', b'python-httpx/0.7.6'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - end_stream stream_id=1
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=0 event=<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.MAX_CONCURRENT_STREAMS, original_value=None, new_value=100), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=1048576), ChangedSetting(setting=SettingCodes.MAX_HEADER_LIST_SIZE, original_value=None, new_value=16384)}>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'301'), (b'location', b'https://www.google.com/'), (b'content-type', b'text/html; charset=UTF-8'), (b'date', b'Wed, 06 Nov 2019 18:18:56 GMT'), (b'expires', b'Fri, 06 Dec 2019 18:18:56 GMT'), (b'cache-control', b'public, max-age=2592000'), (b'server', b'gws'), (b'content-length', b'220'), (b'x-xss-protection', b'0'), (b'x-frame-options', b'SAMEORIGIN'), (b'alt-svc', b'quic=":443"; ma=2592000; v="46,43",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000')]>
+DEBUG [2019-11-06 19:18:56] httpx.client - HTTP Request: GET https://google.com "HTTP/2 301 Moved Permanently"
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.google.com' port=443)
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
+TRACE [2019-11-06 19:18:56] httpx.config - load_ssl_context verify=True cert=None trust_env=True http_versions=HTTPVersionConfig(['HTTP/1.1', 'HTTP/2'])
+TRACE [2019-11-06 19:18:56] httpx.config - load_verify_locations cafile=/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/certifi/cacert.pem
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection - start_connect host='www.google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection - connected http_version='HTTP/2'
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - send_headers stream_id=1 method='GET' target='/' headers=[(b':method', b'GET'), (b':authority', b'www.google.com'), (b':scheme', b'https'), (b':path', b'/'), (b'user-agent', b'python-httpx/0.7.6'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - end_stream stream_id=1
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=0 event=<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.MAX_CONCURRENT_STREAMS, original_value=None, new_value=100), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=1048576), ChangedSetting(setting=SettingCodes.MAX_HEADER_LIST_SIZE, original_value=None, new_value=16384)}>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'200'), (b'date', b'Wed, 06 Nov 2019 18:18:56 GMT'), (b'expires', b'-1'), (b'cache-control', b'private, max-age=0'), (b'content-type', b'text/html; charset=ISO-8859-1'), (b'p3p', b'CP="This is not a P3P policy! See g.co/p3phelp for more info."'), (b'content-encoding', b'gzip'), (b'server', b'gws'), (b'content-length', b'5073'), (b'x-xss-protection', b'0'), (b'x-frame-options', b'SAMEORIGIN'), (b'set-cookie', b'1P_JAR=2019-11-06-18; expires=Fri, 06-Dec-2019 18:18:56 GMT; path=/; domain=.google.com; SameSite=none'), (b'set-cookie', b'NID=190=m8G9qLxCz2_4HbZI02ON2HTJF4xTvOhoJiS57Hm-OJrNS2eY20LfXMR_u-mLjujeshW5-BTezI69OGpHksT4ZK2TCDsWeU0DF7AmDTjjXFOdj30eIUTpNq7r9aWRvI8UrqiwlIsLkE8Ee3t5PiIiVdSMUcji7dkavGlMUpkMXU8; expires=Thu, 07-May-2020 18:18:56 GMT; path=/; domain=.google.com; HttpOnly'), (b'alt-svc', b'quic=":443"; ma=2592000; v="46,43",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000')]>
+DEBUG [2019-11-06 19:18:56] httpx.client - HTTP Request: GET https://www.google.com/ "HTTP/2 200 OK"
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:5186, data:1f8b08000000000002ffc55af97adb4692ff3f4f>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:221, data:>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
+TRACE [2019-11-06 19:18:56] httpx.dispatch.connection - close_connection
 ```
 
 `SSLKEYLOGFILE`
diff --git a/httpx/client.py b/httpx/client.py
index 060dad0..d54d2fd 100644
--- a/httpx/client.py
+++ b/httpx/client.py
@@ -49,7 +49,9 @@ from .models import (
     ResponseContent,
     URLTypes,
 )
-from .utils import ElapsedTimer, get_environment_proxies, get_netrc
+from .utils import ElapsedTimer, get_environment_proxies, get_logger, get_netrc
+
+logger = get_logger(__name__)
 
 
 class BaseClient:
@@ -241,6 +243,12 @@ class BaseClient:
                 finally:
                     await response.close()
 
+            status = f"{response.status_code} {response.reason_phrase}"
+            response_line = f"{response.http_version} {status}"
+            logger.debug(
+                f'HTTP Request: {request.method} {request.url} "{response_line}"'
+            )
+
             return response
 
         def wrap(
diff --git a/httpx/utils.py b/httpx/utils.py
index bf3420c..6516af6 100644
--- a/httpx/utils.py
+++ b/httpx/utils.py
@@ -194,6 +194,7 @@ def get_logger(name: str) -> Logger:
 
     if not _LOGGER_INITIALIZED:
         _LOGGER_INITIALIZED = True
+        logging.addLevelName(TRACE_LOG_LEVEL, "TRACE")
 
         log_level = os.environ.get("HTTPX_LOG_LEVEL", "").upper()
         if log_level in ("DEBUG", "TRACE"):
@@ -202,8 +203,8 @@ def get_logger(name: str) -> Logger:
             handler = logging.StreamHandler(sys.stderr)
             handler.setFormatter(
                 logging.Formatter(
-                    fmt="%(asctime)s.%(msecs)03d - %(name)s - %(message)s",
-                    datefmt="%H:%M:%S",
+                    fmt="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
+                    datefmt="%Y-%m-%d %H:%M:%S",
                 )
             )
             logger.addHandler(handler)


Test patch:
diff --git a/tests/conftest.py b/tests/conftest.py
index c696889..ef57cae 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -69,6 +69,8 @@ async def app(scope, receive, send):
         await echo_body(scope, receive, send)
     elif scope["path"].startswith("/echo_headers"):
         await echo_headers(scope, receive, send)
+    elif scope["path"].startswith("/redirect_301"):
+        await redirect_301(scope, receive, send)
     else:
         await hello_world(scope, receive, send)
 
@@ -147,6 +149,17 @@ async def echo_headers(scope, receive, send):
     await send({"type": "http.response.body", "body": json.dumps(body).encode()})
 
 
+async def redirect_301(scope, receive, send):
+    await send(
+        {
+            "type": "http.response.start",
+            "status": 301,
+            "headers": [[b"location", b"/"]],
+        }
+    )
+    await send({"type": "http.response.body"})
+
+
 SERVER_SCOPE = "session"
 
 
diff --git a/tests/test_utils.py b/tests/test_utils.py
index 959fbf8..1da08fa 100644
--- a/tests/test_utils.py
+++ b/tests/test_utils.py
@@ -108,6 +108,7 @@ async def test_logs_debug(server, capsys):
             response = await client.get(server.url)
             assert response.status_code == 200
     stderr = capsys.readouterr().err
+    assert 'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"' in stderr
     assert "httpx.dispatch.connection_pool" not in stderr
 
 
@@ -118,9 +119,28 @@ async def test_logs_trace(server, capsys):
             response = await client.get(server.url)
             assert response.status_code == 200
     stderr = capsys.readouterr().err
+    assert 'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"' in stderr
     assert "httpx.dispatch.connection_pool" in stderr
 
 
+@pytest.mark.asyncio
+async def test_logs_redirect_chain(server, capsys):
+    with override_log_level("debug"):
+        async with httpx.AsyncClient() as client:
+            response = await client.get(server.url.copy_with(path="/redirect_301"))
+            assert response.status_code == 200
+
+    stderr = capsys.readouterr().err.strip()
+    redirected_request_line, ok_request_line = stderr.split("\n")
+    assert redirected_request_line.endswith(
+        "HTTP Request: GET http://127.0.0.1:8000/redirect_301 "
+        '"HTTP/1.1 301 Moved Permanently"'
+    )
+    assert ok_request_line.endswith(
+        'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"'
+    )
+
+
 def test_get_ssl_cert_file():
     # Two environments is not set.
     assert get_ca_bundle_from_env() is None