How can trace a request?

[lamb]

In golang can trace a request like this, how can trace a request use reqwest?

trace := &httptrace.ClientTrace{
		DNSStart: func(info httptrace.DNSStartInfo) {
			dnsStart = now()
		},
		DNSDone: func(dnsInfo httptrace.DNSDoneInfo) {
			dnsDuration = now() - dnsStart
		},
		GetConn: func(h string) {
			connectStart = now()
		},
		GotConn: func(connInfo httptrace.GotConnInfo) {
			if !connInfo.Reused {
				connectDuration = now() - connectStart
			}
			requestStart = now()
		},
		WroteRequest: func(w httptrace.WroteRequestInfo) {
			requestDuration = now() - requestStart
			delayStart = now()
		},
		GotFirstResponseByte: func() {
			delayDuration = now() - delayStart
			responseStart = now()
		},
	}

[apicize]

I found a way to sort of do what you want to do, but I'm not super thrilled with the approach. I have an HTTP testing app and wanted to create a "console" what would show request traffic. In the example below I am watching for reqwest TRACE messages and dispatching them to an event handler (I'm using Tauri, but that isn't material here). Crates like reqwest_middleware didn't work for me because there was no way to get to the request/response bodies.

Basically, the only way I found to get the entire request and response is to use the trace logging included in reqwest. There's some overhead with doing this.

1. You have to set log's level to TRACE, which means that every crate in your application will be dispatching TRACE log entries. Even though most logging providers give you a way to display or not display entries based upon target and level, the log's log_enabled macro is global, not per target, so you still incur the overhead of generating, if not rendering trace level data in any dependency that generates trace log entries.

2. Logged data is only available as fmt::Arguments. Which means that you have to parse (regex) it if you want to pair up reads and writes (connection entries do not contain an identifier, so they are not super-useful).

3. Some of the stats you have do not appear to be available.

Make sure your ClientBuilder calls .connection_verbose(true)

My log processing mechanism looks like this...

use chrono::Local;
use log::{Metadata, Record};
use regex::Regex;
use serde::Serialize;
use tauri::{AppHandle, Emitter};

pub struct ReqwestLogger {
    regex_readwrite: Regex,
    regex_connect: Regex,
    app: AppHandle,
}

#[derive(Serialize)]
pub struct ReqwestEventConnect<'a> {
    pub timestamp: &'a str,
    pub host: &'a str,
}

#[derive(Serialize)]
pub struct ReqwestEventRead<'a> {
    pub timestamp: &'a str,
    pub id: &'a str,
    pub data: &'a str,
}

#[derive(Serialize)]
pub struct ReqwestEventWrite<'a> {
    pub timestamp: &'a str,
    pub id: &'a str,
    pub data: &'a str,
}

#[derive(Serialize)]
#[serde(tag = "event")]
pub enum ReqwestEvent<'a> {
    Connect(ReqwestEventConnect<'a>),
    Read(ReqwestEventRead<'a>),
    Write(ReqwestEventWrite<'a>),
}

impl ReqwestLogger {
    pub fn new(app: AppHandle) -> Self {
        ReqwestLogger {
            regex_readwrite: Regex::new(r#"^([0-9a-f]+) (read|write): (b".*")$"#).unwrap(),
            regex_connect: Regex::new(r#"starting new connection: (.*)"#).unwrap(),
            app,
        }
    }
}

impl log::Log for ReqwestLogger {
    fn enabled(&self, _: &Metadata) -> bool {
        true
    }

    fn log(&self, record: &Record) {
        let target = record.target();
        if target == "reqwest::connect" {
            let args = record.args().to_string();
            if let Some(result) = self.regex_connect.captures(&args) {
                if let Some(host) = result.get(1) {
                    self.app
                        .emit(
                            "log",
                            serde_json::to_string(&ReqwestEvent::Connect(ReqwestEventConnect {
                                timestamp: Local::now()
                                    .format("%H:%M:%S.%.3f")
                                    .to_string()
                                    .as_str(),
                                host: host.as_str(),
                            }))
                            .unwrap(),
                        )
                        .unwrap();
                }
            }
        } else if target == "reqwest::connect::verbose" {
            let args = record.args().to_string();
            if let Some(result) = self.regex_readwrite.captures(&args) {
                if let Some(request_id) = result.get(1) {
                    if let Some(operation) = result.get(2) {
                        if let Some(data) = result.get(3) {
                            if operation.as_str() == "read" {
                                self.app
                                    .emit(
                                        "log",
                                        serde_json::to_string(&ReqwestEvent::Read(
                                            ReqwestEventRead {
                                                timestamp: Local::now()
                                                    .format("%H:%M:%S.%.3f")
                                                    .to_string()
                                                    .as_str(),
                                                id: request_id.as_str(),
                                                data: data.as_str(),
                                            },
                                        ))
                                        .unwrap(),
                                    )
                                    .unwrap();
                            } else {
                                self.app
                                    .emit(
                                        "log",
                                        serde_json::to_string(&ReqwestEvent::Write(
                                            ReqwestEventWrite {
                                                timestamp: Local::now()
                                                    .format("%H:%M:%S.%.3f")
                                                    .to_string()
                                                    .as_str(),
                                                id: request_id.as_str(),
                                                data: data.as_str(),
                                            },
                                        ))
                                        .unwrap(),
                                    )
                                    .unwrap();
                            }
                        }
                    }
                }
            }
        }
    }

    fn flush(&self) {}
}

In my app, I initialize the logger using OnceLock, since log is static lifetime:

static REQWEST_LOGGER: OnceLock<ReqwestLogger> = OnceLock::new();

fn main() {
    tauri::Builder::default()
        .setup(|app| {
            /// stuff...
            // Initialize log hook to monitor Reqwest activity
            let _ =
                log::set_logger(REQWEST_LOGGER.get_or_init(|| ReqwestLogger::new(app.handle().clone())));
            // yah, this is global :( ...
            log::set_max_level(log::LevelFilter::Trace);            
        }
}

IMHO, in a perfect world, Reqwest wouldn't be relying on logging to do this sort of introspection. There is overhead no matter what when doing something like this, because the response can only be streamed once as its coming in. So, the utility of something like this in production application is kind of an edge-case, so I see why they don't do it.

Hope this helps...