Add DEBUG logs of HTTP requests (#502)

diff --git a/docs/environment_variables.md b/docs/environment_variables.md
index 74c2243d15853cd515d81463cd4e91def3f448ca..15723fb4d027783b80594af694c048198b4f701b 100644 (file)
--- 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 060dad0a65ef551d29f652e7e6e88b0791b52d93..d54d2fd62c420176fb5585f9b973f81232f7de3e 100644 (file)
--- 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 bf3420cea1e617b3e31b75b5f574754910772fac..6516af6b4ec5fc5b2a52fb742f462ef884a351eb 100644 (file)
--- 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)

diff --git a/tests/conftest.py b/tests/conftest.py
index c6968894d53af0602c82d3fd291803396c85ec90..ef57caef30be072b9673f3718988bea924fc211e 100644 (file)
--- 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 959fbf8f663c84c3e3cd5ebd2695b74723b9e45a..1da08fae24b24cc4bda56d10130be469aa9f64f7 100644 (file)
--- 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