Repository: seanmonstar/reqwest (language: rust)

Issue:
Logging requests
Is there a simple way to log requests ?

For example, when I use the Python requests library:

```python
session = requests.Session()
session.post(URL, headers=headers, params=request_params, data=form_data)
```

when setting the log to DEBUG I get:

```
2020-01-11 16:19:39,505 [DEBUG] Starting new HTTPS connection (1):foo.bar.com:443
2020-01-11 16:19:40,595 [DEBUG] https://foo.bar.com:443 "POST /baz HTTP/1.1" 200 None
```

which is quite useful, and surprisingly low on noise. 

OTOH, when using reqwest, setting the log level to debug outputs:

```
[2020-01-11T15:29:19Z DEBUG hyper::client::connect::dns] resolving host="foo.bar.com"
[2020-01-11T15:29:19Z DEBUG hyper::client::connect::http] connecting to 123.456.789.123:443
[2020-01-11T15:29:19Z DEBUG hyper::client::connect::http] connected to Some(V4(123.456.789.123:443))
[2020-01-11T15:29:19Z DEBUG hyper::proto::h1::io] flushed 269 bytes
[2020-01-11T15:29:19Z DEBUG hyper::proto::h1::io] flushed 556 bytes
[2020-01-11T15:29:19Z DEBUG hyper::proto::h1::io] flushed 73 bytes
[2020-01-11T15:29:20Z DEBUG hyper::proto::h1::io] read 1369 bytes
[2020-01-11T15:29:20Z DEBUG hyper::proto::h1::io] parsed 20 headers
[2020-01-11T15:29:20Z DEBUG hyper::proto::h1::conn] incoming body is chunked encoding
[2020-01-11T15:29:20Z DEBUG hyper::proto::h1::decode] incoming chunked header: 0x29EF (10735 bytes)
[2020-01-11T15:29:20Z DEBUG cookie_store::cookie_store] inserting Set-Cookie 'Cookie { cookie_string: Some("__cfduid=sa7dsa6d86as7sda67ad6; expires=Mon, 10-Feb-20 15:29:19 GMT; path=/; domain=.foo.bar.com; HttpOnly; SameSite=Lax; Secure"), name: Indexed(0, 8), value: Indexed(9, 52), expires: None, max_age: None, domain: Some(Indexed(107, 121)), path: Some(Indexed(96, 97)), secure: Some(true), http_only: Some(true), same_site: Some(Lax) }'
[2020-01-11T15:29:20Z DEBUG cookie_store::cookie_store] inserting Set-Cookie 'Cookie { cookie_string: Some("org.fooframework.web.servlet.i18n.CookieLocaleResolver.LOCALE=en; Path=/"), name: Indexed(0, 64), value: Indexed(65, 67), expires: None, max_age: None, domain: None, path: Some(Indexed(74, 75)), secure: None, http_only: None, same_site: None }'
[2020-01-11T15:29:20Z DEBUG cookie_store::cookie_store] inserting Set-Cookie 'Cookie { cookie_string: Some("STUFF=asdasdas-das-sda-ds-das; Path=/sso/; Secure; HttpOnly"), name: Indexed(0, 7), value: Indexed(8, 44), expires: None, max_age: None, domain: None, path: Some(Indexed(51, 56)), secure: Some(true), http_only: Some(true), same_site: None }'
....dozens or so more cookies....
[2020-01-11T15:29:20Z DEBUG reqwest::async_impl::response] Response: '200 OK' for https://foo.bar.com
```

which is much noisier and way less useful to me as an application developer since:

* it does not really show the kind of request (a POST in this case) - this is pretty much the main information I cared about. The Python requests library puts it upfront, but reqwest does not show it

* name: Indexed(0, 8) is not very useful in any kind of logs for the cookies. This might be useful for somebody working on the cookie_store library itself, but it is not useful to me as an application developer.

* when bytes are read, flushed, etc. aren't really that relevant for me either, at least, not while debugging my application - they might be relevant if I would be debugging a performance issue, or working on hyper itself (no idea, but it might be worth it to use `trace!` for this, instead of `debug!`).

Some of these issues should probably be filled on downstream crates, but the logging history needs to be coherent for an application developer. 

---

If I go down to RUST_LOG=TRACE, then I see the POST request being traced within hyper, 

```
[2020-01-11T16:00:04Z TRACE hyper::proto::h1::role] Client::encode method=POST, body=Some(Unknown)
```

as long as about 4x as much noise in general, yet I still don't get any information about what the content of the POST actually was :/


Discussion / hints:
If you're using something like env_logger, you can use `RUST_LOG=reqwest=debug` to ignore the logs from dependencies. In reqwest, we could probably add a couple more useful logs, like around starting connections, requests, if a proxy is used...

To see the contents of the headers and body, you can enable the `connection_verbose` client builder setting, and then set log level to trace. It's purposefully an additional step to prevent accidental logging of sensitive material (if you'd just turned on all trace logs and didn't know what they could contain).
> In reqwest, we could probably add a couple more useful logs, like around starting connections, requests, if a proxy is used...

That would be very helpful.

Fix patch:
diff --git a/src/async_impl/client.rs b/src/async_impl/client.rs
index b9cbee679..231953efc 100644
--- a/src/async_impl/client.rs
+++ b/src/async_impl/client.rs
@@ -1189,13 +1189,13 @@ impl Future for PendingRequest {
 
                     match action {
                         redirect::ActionKind::Follow => {
+                            debug!("redirecting '{}' to '{}'", self.url, loc);
                             self.url = loc;
 
                             let mut headers =
                                 std::mem::replace(self.as_mut().headers(), HeaderMap::new());
 
                             remove_sensitive_headers(&mut headers, &self.url, &self.urls);
-                            debug!("redirecting to {:?} '{}'", self.method, self.url);
                             let uri = expect_uri(&self.url);
                             let body = match self.body {
                                 Some(Some(ref body)) => Body::reusable(body.clone()),
@@ -1224,7 +1224,7 @@ impl Future for PendingRequest {
                             continue;
                         }
                         redirect::ActionKind::Stop => {
-                            debug!("redirect_policy disallowed redirection to '{}'", loc);
+                            debug!("redirect policy disallowed redirection to '{}'", loc);
                         }
                         redirect::ActionKind::Error(err) => {
                             return Poll::Ready(Err(crate::error::redirect(
@@ -1235,6 +1235,8 @@ impl Future for PendingRequest {
                     }
                 }
             }
+
+            debug!("response '{}' for {}", res.status(), self.url);
             let res = Response::new(res, self.url.clone(), self.client.gzip, self.timeout.take());
             return Poll::Ready(Ok(res));
         }
diff --git a/src/async_impl/response.rs b/src/async_impl/response.rs
index 17d05c020..c8521105e 100644
--- a/src/async_impl/response.rs
+++ b/src/async_impl/response.rs
@@ -9,7 +9,6 @@ use http;
 use hyper::client::connect::HttpInfo;
 use hyper::header::CONTENT_LENGTH;
 use hyper::{HeaderMap, StatusCode, Version};
-use log::debug;
 use mime::Mime;
 #[cfg(feature = "json")]
 use serde::de::DeserializeOwned;
@@ -50,7 +49,6 @@ impl Response {
         let mut headers = parts.headers;
         let decoder = Decoder::detect(&mut headers, Body::response(body, timeout), gzip);
 
-        debug!("Response: '{}' for {}", status, url);
         Response {
             status,
             headers,
diff --git a/src/connect.rs b/src/connect.rs
index 378f2d4bb..3db6a160a 100644
--- a/src/connect.rs
+++ b/src/connect.rs
@@ -293,7 +293,7 @@ impl Connector {
         dst: Uri,
         proxy_scheme: ProxyScheme,
     ) -> Result<Conn, BoxError> {
-        log::trace!("proxy({:?}) intercepts {:?}", proxy_scheme, dst);
+        log::debug!("proxy({:?}) intercepts '{:?}'", proxy_scheme, dst);
 
         let (proxy_dst, _auth) = match proxy_scheme {
             ProxyScheme::Http { host, auth } => (into_uri(Scheme::HTTP, host), auth),
@@ -421,8 +421,7 @@ where
     }
 }
 
-impl Service<Uri> for Connector
-{
+impl Service<Uri> for Connector {
     type Response = Conn;
     type Error = BoxError;
     type Future = Connecting;
@@ -432,6 +431,7 @@ impl Service<Uri> for Connector
     }
 
     fn call(&mut self, dst: Uri) -> Self::Future {
+        log::debug!("starting new connection: {:?}", dst);
         let timeout = self.timeout;
         for prox in self.proxies.iter() {
             if let Some(proxy_scheme) = prox.intercept(&dst) {
diff --git a/src/proxy.rs b/src/proxy.rs
index 25eefe224..313fe6810 100644
--- a/src/proxy.rs
+++ b/src/proxy.rs
@@ -55,7 +55,7 @@ pub struct Proxy {
 /// A particular scheme used for proxying requests.
 ///
 /// For example, HTTP vs SOCKS5
-#[derive(Clone, Debug)]
+#[derive(Clone)]
 pub enum ProxyScheme {
     Http {
         auth: Option<HeaderValue>,
@@ -434,6 +434,38 @@ impl ProxyScheme {
     }
 }
 
+impl fmt::Debug for ProxyScheme {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        match self {
+            ProxyScheme::Http {
+                auth: _auth,
+                host,
+            } => {
+                write!(f, "http://{}", host)
+            },
+            ProxyScheme::Https {
+                auth: _auth,
+                host,
+            } => {
+                write!(f, "https://{}", host)
+            },
+            #[cfg(feature = "socks")]
+            ProxyScheme::Socks5 {
+                addr,
+                auth: _auth,
+                remote_dns,
+            } => {
+                let h = if *remote_dns {
+                    "h"
+                } else {
+                    ""
+                };
+                write!(f, "socks5{}://{}", h, addr)
+            }
+        }
+    }
+}
+
 type SystemProxyMap = HashMap<String, ProxyScheme>;
 
 #[derive(Clone, Debug)]


Test patch: