TraceLayer only logs request method and path, if debug logging is enabled

[hannobraun]

Bug Report

Version

v0.1.1

Platform

Linux 5.13.10-arch1-1 #1 SMP PREEMPT Thu, 12 Aug 2021 21:59:14 +0000 x86_64 GNU/Linux

Description

I'm configuring a TraceLayer like this:

TraceLayer::new_for_http()
    .on_request(trace::DefaultOnRequest::new().level(Level::INFO))
    .on_response(trace::DefaultOnResponse::new().level(Level::INFO))

When executing my program with RUST_LOG=info cargo run, I get the following log output:

INFO tower_http::trace::on_request: started processing request
INFO tower_http::trace::on_response: finished processing request latency=0 ms status=200

The requests are logged, but the request method and path are missing.

If I run RUST_LOG=debug cargo run, both are there:

INFO request{method=GET uri=/ version=HTTP/1.1}: tower_http::trace::on_request: started processing request
INFO request{method=GET uri=/ version=HTTP/1.1}: tower_http::trace::on_response: finished processing request latency=1 ms status=200

I believe that the reason for that is that the make_span method is using tracing::debug_span, regardless of any other configuration:

tower-http/tower-http/src/trace/make_span.rs

Lines 58 to 75 in e1252c2

	fn make_span(&mut self, request: &Request<B>) -> Span {
	if self.include_headers {
	tracing::debug_span!(
	"request",
	method = %request.method(),
	uri = %request.uri(),
	version = ?request.version(),
	headers = ?request.headers(),
	)
	} else {
	tracing::debug_span!(
	"request",
	method = %request.method(),
	uri = %request.uri(),
	version = ?request.version(),
	)
	}
	}

I'm not sure what is supposed to be done here. The straight-forward fix is to add a Level field to DefaultMakeSpan (along with a method to set it), but that makes no sense to me, API-wise. If I configure my requests to be logged with INFO, I don't expect to need extra steps to get basic information with my log messages.

[hannobraun]

I've submitted #124 to address this.

[hannobraun]

As @davidbarsky pointed out in #124, the existing TraceLayer::make_span_with is enough to work around this issue, as you can pass your own MakeSpan implementation there and aren't beholden to what DefaultMakeSpan does.

This addresses my problem, but maybe this issue should stay open to track the weirdness of the API and resulting potential for confusion? I don't know. I'm leaving it open and letting the maintainers decide.

[davidpdrsn]

I think you're right that the API is inconsistent since DefaultMakeSpan doesn't have a builder method for setting the span level. I'll review your PR tomorrow 😊