Receiving ">>> Request guard … is forwarding" messages with log_level=critical

[jeeger]

Description

I'm running a small Rocket application (written for learning). I've set the log level to critical for the release build. I've written a FromRequest implementation for a custom UserId type that returns a Forward result if it can't extract a user ID from the request cookies. Despite setting the log level to critical via Rocket.toml, Rocket still writes ">> Request guard UserId is forwarding." to the lock.

To Reproduce

Implement a custom type with a FromRequest implementation, and return an Outcome::Forward. Set the log level to critical in Rocket.toml. You will receive some "Forwarding" messages.

(I can try and write code to reproduce if necessary, but I hope the bug is clear enough without a repro)

Expected Behavior

No output about my custom type.

Environment:

• OS Distribution and Kernel: various
• Rocket Version: 0.5.0

[jeeger]

Reproduction code:

main.rs:

use std::convert::Infallible;

#[macro_use]
extern crate rocket;

use rocket::{http::Status, outcome::Outcome, request::FromRequest, Request};

struct UserType {
    _thing: String,
}

#[rocket::async_trait]
impl<'r> FromRequest<'r> for UserType {
    type Error = Infallible;
    // Required method
    async fn from_request(
        _request: &'r Request<'_>,
    ) -> rocket::request::Outcome<Self, Self::Error> {
        Outcome::Forward(Status::from_code(200).unwrap())
    }
}

#[get("/", rank = 1)]
async fn test(_ut: UserType) -> &'static str {
    &"test"
}

#[get("/", rank = 2)]
async fn test2() -> &'static str {
    &"test2"
}

#[launch]
fn rocket() -> _ {
    rocket::build().mount("/", routes![test, test2])
}

Cargo.toml:

[package]
name = "rocket-bug"
version = "0.1.0"
edition = "2021"

# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html

[dependencies]
rocket = "0.5.0"

Run with ROCKET_LOG_LEVEL=critical cargo run

[SergioBenitez]

Can you post the complete log output, from the moment the application starts to the moment it logs the forward and the rest of the request?

[jeeger]

Here you go!

Rocket has launched from http://127.0.0.1:8000
   >> Request guard `UserType` is forwarding.
Warning: Received SIGINT. Requesting shutdown.

[jeeger]

rustc version is rustc 1.76.0-nightly (a1a37735c 2023-11-23).

[SergioBenitez]

Ah, got it. This is by design. We log the forward message as a warning, and warnings are included in the "critical" log level. This is because some forwards may indeed be critical to resolving an issue in production. Of course, other forwards may not, but we take a conservative approach here and log them in case they are. Nevertheless, I understand that it can be frustrating to have log output when you don't want it.

I see a few options in Rocket:

1. Get rid of LogLevel's coalescing of logging levels and simply expose the 6 log levels. This would allow you to set the LOG_LEVEL to error, bypassing this message.
2. Do nothing and wait for Improve Logging: Migrate to tracing #21 to finally land.

A few options outside of Rocket:

1. Register your own log logger before calling build(). Rocket won't replace it, and you can
   filter messages however you like. IE, with env_logger:

   #[launch]
   fn rocket() -> _ {
       env_logger::init();
     
       rocket::build()
   }

2. Filter your logs post-facto.

I'm inclined to suggest we do 2) in Rocket, given the options available outside of Rocket. I wouldn't be opposed to a PR that implements 1), however, as long as the implementation keeps the existing log levels for backwards compatibility.

Given that there's no specific issue here, as things work as intended, I'm going to close this issue. But please feel free to submit a PR if you'd like to extend Rocket's log levels to make this easier to handle.

[jeeger]

Thanks for the comprehensive answer!