Implement 'Trace' trait. Use structured logging.

This commit:
  - Converts most log messages into structured messages.
  - Implements an initial request ID layer.
  - Implements pretty and compact loggers.
This commit is contained in:
Sergio Benitez 2024-05-08 03:52:40 -07:00
parent ff6da900a0
commit 8a1c91b7d5
29 changed files with 1274 additions and 697 deletions

View File

@ -33,7 +33,7 @@ uuid = ["uuid_", "rocket_http/uuid"]
tls = ["rustls", "tokio-rustls", "rustls-pemfile"]
mtls = ["tls", "x509-parser"]
tokio-macros = ["tokio/macros"]
trace = ["tracing-subscriber", "tinyvec", "rustls?/logging", "tokio-rustls?/logging", "multer/log"]
trace = ["tracing-subscriber", "tinyvec", "thread_local", "rustls?/logging", "tokio-rustls?/logging", "multer/log"]
[dependencies]
# Optional serialization dependencies.
@ -78,6 +78,7 @@ state = "0.6"
# tracing
tracing = { version = "0.1.40", default-features = false, features = ["std", "attributes"] }
tinyvec = { version = "1.6", optional = true, features = ["std", "rustc_1_57"] }
thread_local = { version = "1.1", optional = true }
[dependencies.tracing-subscriber]
version = "0.3.18"

View File

@ -10,7 +10,7 @@ use crate::config::{ShutdownConfig, Ident, CliColors};
use crate::request::{self, Request, FromRequest};
use crate::http::uncased::Uncased;
use crate::data::Limits;
use crate::util::Formatter;
use crate::trace::traceable::Traceable;
/// Rocket server configuration.
///
@ -303,98 +303,6 @@ impl Config {
pub fn from<T: Provider>(provider: T) -> Self {
Self::try_from(provider).unwrap_or_else(bail_with_config_error)
}
#[cfg(feature = "secrets")]
fn known_secret_key_used(&self) -> bool {
const KNOWN_SECRET_KEYS: &[&str] = &[
"hPRYyVRiMyxpw5sBB1XeCMN1kFsDCqKvBi2QJxBVHQk="
];
KNOWN_SECRET_KEYS.iter().any(|&key_str| {
let value = figment::value::Value::from(key_str);
self.secret_key == value.deserialize().expect("known key is valid")
})
}
#[tracing::instrument(name = "config", skip_all, fields(profile = %figment.profile()))]
pub(crate) fn pretty_print(&self, figment: &Figment) {
info! {
name: "values",
http2 = cfg!(feature = "http2"),
log_level = self.log_level.map(|l| l.as_str()),
cli_colors = %self.cli_colors,
workers = self.workers,
max_blocking = self.max_blocking,
ident = %self.ident,
ip_header = self.ip_header.as_ref().map(|s| s.as_str()),
proxy_proto_header = self.proxy_proto_header.as_ref().map(|s| s.as_str()),
limits = %Formatter(|f| f.debug_map()
.entries(self.limits.limits.iter().map(|(k, v)| (k.as_str(), v.to_string())))
.finish()),
temp_dir = %self.temp_dir.relative().display(),
keep_alive = (self.keep_alive != 0).then_some(self.keep_alive),
shutdown.ctrlc = self.shutdown.ctrlc,
shutdown.signals = %{
#[cfg(not(unix))] {
"disabled (not unix)"
}
#[cfg(unix)] {
Formatter(|f| f.debug_set()
.entries(self.shutdown.signals.iter().map(|s| s.as_str()))
.finish())
}
},
shutdown.grace = self.shutdown.grace,
shutdown.mercy = self.shutdown.mercy,
shutdown.force = self.shutdown.force,
};
for param in Self::PARAMETERS {
if let Some(source) = figment.find_metadata(param) {
trace! {
param,
%source.name,
source.source = source.source.as_ref().map(|s| s.to_string()),
}
}
}
// Check for now deprecated config values.
for (key, replacement) in Self::DEPRECATED_KEYS {
if let Some(source) = figment.find_metadata(key) {
warn! {
name: "deprecated",
key,
replacement,
%source.name,
source.source = source.source.as_ref().map(|s| s.to_string()),
"config key `{key}` is deprecated and has no meaning"
}
}
}
#[cfg(feature = "secrets")] {
if !self.secret_key.is_provided() {
warn! {
name: "volatile_secret_key",
"secrets enabled without configuring a stable `secret_key`; \
private/signed cookies will become unreadable after restarting; \
disable the `secrets` feature or configure a `secret_key`; \
this becomes a hard error in non-debug profiles",
}
}
if self.known_secret_key_used() {
warn! {
name: "insecure_secret_key",
"The configured `secret_key` is exposed and insecure. \
The configured key is publicly published and thus insecure. \
Try generating a new key with `head -c64 /dev/urandom | base64`."
}
}
}
}
}
/// Associated constants for default profiles.
@ -416,11 +324,6 @@ impl Config {
/// Associated constants for stringy versions of configuration parameters.
impl Config {
/// The stringy parameter name for setting/extracting [`Config::profile`].
///
/// This isn't `pub` because setting it directly does nothing.
const PROFILE: &'static str = "profile";
/// The stringy parameter name for setting/extracting [`Config::workers`].
pub const WORKERS: &'static str = "workers";
@ -465,12 +368,22 @@ impl Config {
Self::CLI_COLORS,
];
/// The stringy parameter name for setting/extracting [`Config::profile`].
///
/// This isn't `pub` because setting it directly does nothing.
const PROFILE: &'static str = "profile";
/// An array of deprecated stringy parameter names.
const DEPRECATED_KEYS: &'static [(&'static str, Option<&'static str>)] = &[
pub(crate) const DEPRECATED_KEYS: &'static [(&'static str, Option<&'static str>)] = &[
("env", Some(Self::PROFILE)), ("log", Some(Self::LOG_LEVEL)),
("read_timeout", None), ("write_timeout", None),
];
/// Secret keys that have been used in docs or leaked otherwise.
#[cfg(feature = "secrets")]
pub(crate) const KNOWN_SECRET_KEYS: &'static [&'static str] = &[
"hPRYyVRiMyxpw5sBB1XeCMN1kFsDCqKvBi2QJxBVHQk="
];
}
impl Provider for Config {
@ -520,34 +433,7 @@ pub fn bail_with_config_error<T>(error: figment::Error) -> T {
}
#[doc(hidden)]
// FIXME: Remove this funtion.
pub fn pretty_print_error(error: figment::Error) {
use figment::error::{OneOf as V, Kind::*};
for e in error {
let span = tracing::error_span! {
"error: configuration",
key = (!e.path.is_empty()).then_some(&e.path).and_then(|path| {
let (profile, metadata) = (e.profile.as_ref()?, e.metadata.as_ref()?);
Some(metadata.interpolate(profile, path))
}),
source.name = e.metadata.as_ref().map(|m| &*m.name),
source.source = e.metadata.as_ref().and_then(|m| Some(m.source.as_ref()?.to_string())),
};
let _scope = span.enter();
match e.kind {
Message(message) => error!(message),
InvalidType(actual, expected) => error!(name: "invalid type", %actual, expected),
InvalidValue(actual, expected) => error!(name: "invalid value", %actual, expected),
InvalidLength(actual, expected) => error!(name: "invalid length", %actual, expected),
UnknownVariant(actual, v) => error!(name: "unknown variant", actual, expected = %V(v)),
UnknownField(actual, v) => error!(name: "unknown field", actual, expected = %V(v)),
UnsupportedKey(actual, v) => error!(name: "unsupported key", %actual, expected = &*v),
MissingField(value) => error!(name: "missing field", value = &*value),
DuplicateField(value) => error!(name: "duplicate field", value),
ISizeOutOfRange(value) => error!(name: "out of range signed integer", value),
USizeOutOfRange(value) => error!(name: "out of range unsigned integer", value),
Unsupported(value) => error!(name: "unsupported type", %value),
}
}
error.trace_error()
}

View File

@ -77,6 +77,11 @@ impl ErasedRequest {
ErasedRequest { _rocket: rocket, _parts: parts, request, }
}
pub fn inner(&self) -> &Request<'_> {
static_assert_covariance!(Request);
&self.request
}
pub async fn into_response<T, D>(
self,
raw_stream: D,
@ -135,22 +140,22 @@ impl ErasedResponse {
f(&mut self.response)
}
pub fn make_io_handler<'a>(
pub fn make_io_handler<'a, T: 'static>(
&'a mut self,
constructor: impl for<'r> FnOnce(
&'r Request<'r>,
&'a mut Response<'r>,
) -> Option<Box<dyn IoHandler + 'r>>
) -> Option<ErasedIoHandler> {
) -> Option<(T, Box<dyn IoHandler + 'r>)>
) -> Option<(T, ErasedIoHandler)> {
let parent: Arc<ErasedRequest> = self._request.clone();
let io: Option<Box<dyn IoHandler + '_>> = {
let io: Option<(T, Box<dyn IoHandler + '_>)> = {
let parent: &ErasedRequest = &parent;
let parent: &'static ErasedRequest = unsafe { transmute(parent) };
let request: &Request<'_> = &parent.request;
constructor(request, &mut self.response)
};
io.map(|io| ErasedIoHandler { _request: parent, io })
io.map(|(v, io)| (v, ErasedIoHandler { _request: parent, io }))
}
}

View File

@ -47,6 +47,22 @@ impl Fairings {
.chain(self.shutdown.iter())
}
pub fn unique_set(&self) -> Vec<&dyn Fairing> {
iter!(self, self.active().collect::<HashSet<_>>().into_iter())
.map(|v| v.1)
.collect()
// .into_iter()
// .map(|i| )
// if !active_fairings.is_empty() {
// tracing::info_span!("fairings").in_scope(|| {
// for (_, fairing) in iter!(self, active_fairings.into_iter()) {
// let (name, kind) = (fairing.info().name, fairing.info().kind);
// info!(name: "fairing", name, %kind)
// }
// });
// }
}
pub fn add(&mut self, fairing: Box<dyn Fairing>) {
let this = &fairing;
let this_info = this.info();
@ -166,18 +182,6 @@ impl Fairings {
false => Err(&self.failures)
}
}
pub fn pretty_print(&self) {
let active_fairings = self.active().collect::<HashSet<_>>();
if !active_fairings.is_empty() {
tracing::info_span!("fairings").in_scope(|| {
for (_, fairing) in iter!(self, active_fairings.into_iter()) {
let (name, kind) = (fairing.info().name, fairing.info().kind);
info!(name: "fairing", name, %kind)
}
});
}
}
}
impl std::fmt::Debug for Fairings {

View File

@ -142,20 +142,20 @@ impl FileServer {
/// ```
#[track_caller]
pub fn new<P: AsRef<Path>>(path: P, options: Options) -> Self {
use crate::yansi::Paint;
let path = path.as_ref();
if !options.contains(Options::Missing) {
if !options.contains(Options::IndexFile) && !path.is_dir() {
let path = path.display();
error!("FileServer path '{}' is not a directory.", path.primary());
warn_!("Aborting early to prevent inevitable handler error.");
panic!("invalid directory: refusing to continue");
error!(path = %path.display(),
"FileServer path does not point to a directory.\n\
Aborting early to prevent inevitable handler runtime errors.");
panic!("invalid directory path: refusing to continue");
} else if !path.exists() {
let path = path.display();
error!("FileServer path '{}' is not a file.", path.primary());
warn_!("Aborting early to prevent inevitable handler error.");
panic!("invalid file: refusing to continue");
error!(path = %path.display(),
"FileServer path does not point to a file.\n\
Aborting early to prevent inevitable handler runtime errors.");
panic!("invalid file path: refusing to continue");
}
}

View File

@ -554,17 +554,16 @@ impl<'r> FromData<'r> for Capped<TempFile<'_>> {
type Error = io::Error;
async fn from_data(req: &'r Request<'_>, data: Data<'r>) -> data::Outcome<'r, Self> {
use yansi::Paint;
let has_form = |ty: &ContentType| ty.is_form_data() || ty.is_form();
if req.content_type().map_or(false, has_form) {
let (tf, form) = ("TempFile<'_>".primary(), "Form<TempFile<'_>>".primary());
warn_!("Request contains a form that will not be processed.");
info_!("Bare `{}` data guard writes raw, unprocessed streams to disk.", tf);
info_!("Did you mean to use `{}` instead?", form);
warn!(request.content_type = req.content_type().map(display),
"Request contains a form that is not being processed.\n\
Bare `TempFile` data guard writes raw, unprocessed streams to disk\n\
Perhaps you meant to use `Form<TempFile<'_>>` instead?");
}
TempFile::from(req, data, None, req.content_type().cloned()).await
TempFile::from(req, data, None, req.content_type().cloned())
.await
.or_error(Status::BadRequest)
}
}

View File

@ -1,7 +1,8 @@
use yansi::Paint;
use futures::future::{FutureExt, Future};
use crate::{route, Rocket, Orbit, Request, Response, Data};
use crate::{route, catcher, Rocket, Orbit, Request, Response, Data};
use crate::trace::traceable::Traceable;
use crate::util::Formatter;
use crate::data::IoHandler;
use crate::http::{Method, Status, Header};
use crate::outcome::Outcome;
@ -15,19 +16,17 @@ async fn catch_handle<Fut, T, F>(name: Option<&str>, run: F) -> Option<T>
{
macro_rules! panic_info {
($name:expr, $e:expr) => {{
match $name {
Some(name) => error_!("Handler {} panicked.", name.primary()),
None => error_!("A handler panicked.")
};
error!(handler = name.as_ref().map(display),
"handler panicked\n\
This is an application bug.\n\
A panic in Rust must be treated as an exceptional event.\n\
Panicking is not a suitable error handling mechanism.\n\
Unwinding, the result of a panic, is an expensive operation.\n\
Panics will degrade application performance.\n\
Instead of panicking, return `Option` and/or `Result`.\n\
Values of either type can be returned directly from handlers.\n\
A panic is treated as an internal server error.");
info_!("This is an application bug.");
info_!("A panic in Rust must be treated as an exceptional event.");
info_!("Panicking is not a suitable error handling mechanism.");
info_!("Unwinding, the result of a panic, is an expensive operation.");
info_!("Panics will degrade application performance.");
info_!("Instead of panicking, return `Option` and/or `Result`.");
info_!("Values of either type can be returned directly from handlers.");
warn_!("A panic is treated as an internal server error.");
$e
}}
}
@ -96,8 +95,6 @@ impl Rocket<Orbit> {
data: Data<'r>,
// io_stream: impl Future<Output = io::Result<IoStream>> + Send,
) -> Response<'r> {
info!("{}:", request);
// Remember if the request is `HEAD` for later body stripping.
let was_head_request = request.method() == Method::Head;
@ -105,7 +102,7 @@ impl Rocket<Orbit> {
let mut response = match self.route(request, data).await {
Outcome::Success(response) => response,
Outcome::Forward((data, _)) if request.method() == Method::Head => {
info_!("Autohandling {} request.", "HEAD".primary().bold());
tracing::Span::current().record("autohandled", true);
// Dispatch the request again with Method `GET`.
request._set_method(Method::Get);
@ -155,23 +152,29 @@ impl Rocket<Orbit> {
}
pub(crate) fn extract_io_handler<'r>(
request: &Request<'_>,
request: &'r Request<'_>,
response: &mut Response<'r>,
// io_stream: impl Future<Output = io::Result<IoStream>> + Send,
) -> Option<Box<dyn IoHandler + 'r>> {
) -> Option<(String, Box<dyn IoHandler + 'r>)> {
let upgrades = request.headers().get("upgrade");
let Ok(upgrade) = response.search_upgrades(upgrades) else {
warn_!("Request wants upgrade but no I/O handler matched.");
info_!("Request is not being upgraded.");
info!(
upgrades = %Formatter(|f| f.debug_list()
.entries(request.headers().get("upgrade"))
.finish()),
"request wants upgrade but no i/o handler matched\n\
refusing to upgrade request"
);
return None;
};
if let Some((proto, io_handler)) = upgrade {
info_!("Attempting upgrade with {proto} I/O handler.");
let proto = proto.to_string();
response.set_status(Status::SwitchingProtocols);
response.set_raw_header("Connection", "Upgrade");
response.set_raw_header("Upgrade", proto.to_string());
return Some(io_handler);
response.set_raw_header("Upgrade", proto.clone());
return Some((proto, io_handler));
}
None
@ -181,6 +184,11 @@ impl Rocket<Orbit> {
/// returns success or error, or there are no additional routes to try, in
/// which case a `Forward` with the last forwarding state is returned.
#[inline]
#[tracing::instrument("routing", skip_all, fields(
method = %request.method(),
uri = %request.uri(),
format = request.format().map(display),
))]
async fn route<'s, 'r: 's>(
&'s self,
request: &'r Request<'s>,
@ -191,7 +199,6 @@ impl Rocket<Orbit> {
let mut status = Status::NotFound;
for route in self.router.route(request) {
// Retrieve and set the requests parameters.
info_!("Matched: {}", route);
request.set_route(route);
let name = route.name.as_deref();
@ -200,16 +207,17 @@ impl Rocket<Orbit> {
// Check if the request processing completed (Some) or if the
// request needs to be forwarded. If it does, continue the loop
// (None) to try again.
info_!("{}", outcome.log_display());
route.trace_info();
outcome.trace_info();
match outcome {
o@Outcome::Success(_) | o@Outcome::Error(_) => return o,
Outcome::Forward(forwarded) => (data, status) = forwarded,
}
}
error_!("No matching routes for {}.", request);
Outcome::Forward((data, status))
let outcome = Outcome::Forward((data, status));
outcome.trace_info();
outcome
}
// Invokes the catcher for `status`. Returns the response on success.
@ -219,6 +227,7 @@ impl Rocket<Orbit> {
//
// On catcher error, the 500 error catcher is attempted. If _that_ errors,
// the (infallible) default 500 error cather is used.
#[tracing::instrument("catching", skip_all, fields(status = status.code, uri = %req.uri()))]
pub(crate) async fn dispatch_error<'r, 's: 'r>(
&'s self,
mut status: Status,
@ -227,23 +236,22 @@ impl Rocket<Orbit> {
// We may wish to relax this in the future.
req.cookies().reset_delta();
// Dispatch to the `status` catcher.
if let Ok(r) = self.invoke_catcher(status, req).await {
return r;
}
// If it fails and it's not a 500, try the 500 catcher.
if status != Status::InternalServerError {
error_!("Catcher failed. Attempting 500 error catcher.");
status = Status::InternalServerError;
if let Ok(r) = self.invoke_catcher(status, req).await {
return r;
loop {
// Dispatch to the `status` catcher.
match self.invoke_catcher(status, req).await {
Ok(r) => return r,
// If the catcher failed, try `500` catcher, unless this is it.
Err(e) if status.code != 500 => {
warn!(status = e.map(|r| r.code), "catcher failed: trying 500 catcher");
status = Status::InternalServerError;
}
// The 500 catcher failed. There's no recourse. Use default.
Err(e) => {
error!(status = e.map(|r| r.code), "500 catcher failed");
return catcher::default_handler(Status::InternalServerError, req);
}
}
}
// If it failed again or if it was already a 500, use Rocket's default.
error_!("{} catcher failed. Using Rocket default 500.", status.code);
crate::catcher::default_handler(Status::InternalServerError, req)
}
/// Invokes the handler with `req` for catcher with status `status`.
@ -262,16 +270,14 @@ impl Rocket<Orbit> {
req: &'r Request<'s>
) -> Result<Response<'r>, Option<Status>> {
if let Some(catcher) = self.router.catch(status, req) {
warn_!("Responding with registered {} catcher.", catcher);
let name = catcher.name.as_deref();
catch_handle(name, || catcher.handler.handle(status, req)).await
catcher.trace_info();
catch_handle(catcher.name.as_deref(), || catcher.handler.handle(status, req)).await
.map(|result| result.map_err(Some))
.unwrap_or_else(|| Err(None))
} else {
let code = status.code.blue().bold();
warn_!("No {} catcher registered. Using Rocket default.", code);
Ok(crate::catcher::default_handler(status, req))
info!(name: "catcher", name = "rocket::default", code = status.code,
"no registered catcher: using Rocket default");
Ok(catcher::default_handler(status, req))
}
}
}

View File

@ -86,10 +86,6 @@
//! a type of `Option<S>`. If an `Outcome` is a `Forward`, the `Option` will be
//! `None`.
use std::fmt;
use yansi::{Paint, Color};
use crate::{route, request, response};
use crate::data::{self, Data, FromData};
use crate::http::Status;
@ -101,7 +97,7 @@ use self::Outcome::*;
///
/// See the [top level documentation](crate::outcome) for detailed information.
#[must_use]
#[derive(Clone, Copy, PartialEq, PartialOrd, Eq, Ord, Hash)]
#[derive(Debug, Clone, Copy, PartialEq, PartialOrd, Eq, Ord, Hash)]
pub enum Outcome<S, E, F> {
/// Contains the success value.
Success(S),
@ -710,59 +706,6 @@ crate::export! {
}
}
impl<S, E, F> Outcome<S, E, F> {
#[inline]
fn dbg_str(&self) -> &'static str {
match self {
Success(..) => "Success",
Error(..) => "Error",
Forward(..) => "Forward",
}
}
#[inline]
fn color(&self) -> Color {
match self {
Success(..) => Color::Green,
Error(..) => Color::Red,
Forward(..) => Color::Yellow,
}
}
}
pub(crate) struct Display<'a, 'r>(&'a route::Outcome<'r>);
impl fmt::Display for Display<'_, '_> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{}", "Outcome: ".primary().bold())?;
let color = self.0.color();
match self.0 {
Success(r) => write!(f, "{}({})", "Success".paint(color), r.status().primary()),
Error(s) => write!(f, "{}({})", "Error".paint(color), s.primary()),
Forward((_, s)) => write!(f, "{}({})", "Forward".paint(color), s.primary()),
}
}
}
impl<'r> route::Outcome<'r> {
pub(crate) fn log_display(&self) -> Display<'_, 'r> {
Display(self)
}
}
impl<S, E, F> fmt::Debug for Outcome<S, E, F> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "Outcome::{}", self.dbg_str())
}
}
impl<S, E, F> fmt::Display for Outcome<S, E, F> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{}", self.dbg_str().paint(self.color()))
}
}
/// Conversion trait from some type into an Outcome type.
pub trait IntoOutcome<Outcome> {
/// The type to use when returning an `Outcome::Error`.

View File

@ -1041,16 +1041,16 @@ impl<'r> Request<'r> {
self.routed_segments(0..).get(n)
}
/// Get the segments beginning at the `n`th, 0-indexed, after the mount
/// Get the segments beginning at the `range`, 0-indexed, after the mount
/// point for the currently matched route, if they exist. Used by codegen.
#[inline]
pub fn routed_segments(&self, n: RangeFrom<usize>) -> Segments<'_, Path> {
pub fn routed_segments(&self, range: RangeFrom<usize>) -> Segments<'_, Path> {
let mount_segments = self.route()
.map(|r| r.uri.metadata.base_len)
.unwrap_or(0);
trace!("requesting {}.. ({}..) from {}", n.start, mount_segments, self);
self.uri().path().segments().skip(mount_segments + n.start)
trace!(name: "segments", mount_segments, range.start);
self.uri().path().segments().skip(mount_segments + range.start)
}
// Retrieves the pre-parsed query items. Used by matching and codegen.
@ -1112,10 +1112,14 @@ impl<'r> Request<'r> {
// a security issue with Hyper, there isn't much we can do.
#[cfg(debug_assertions)]
if Origin::parse(uri.as_str()).is_err() {
warn!("Hyper/Rocket URI validity discord: {:?}", uri.as_str());
info_!("Hyper believes the URI is valid while Rocket disagrees.");
info_!("This is likely a Hyper bug with potential security implications.");
warn_!("Please report this warning to Rocket's GitHub issue tracker.");
warn!(
name: "uri_discord",
%uri,
"Hyper/Rocket URI validity discord: {uri}\n\
Hyper believes the URI is valid while Rocket disagrees.\n\
This is likely a Hyper bug with potential security implications.\n\
Please report this warning to Rocket's GitHub issue tracker."
)
}
Origin::new(uri.path(), uri.query().map(Cow::Borrowed))
@ -1200,6 +1204,7 @@ impl fmt::Debug for Request<'_> {
}
}
// FIXME: Remov me to identify dependent `TRACE` statements.
impl fmt::Display for Request<'_> {
/// Pretty prints a Request. Primarily used by Rocket's logging.
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {

View File

@ -244,10 +244,7 @@ impl<'r> FromRequest<'r> for FlashMessage<'r> {
type Error = ();
async fn from_request(req: &'r Request<'_>) -> request::Outcome<Self, Self::Error> {
trace_!("Flash: attempting to retrieve message.");
req.cookies().get(FLASH_COOKIE_NAME).ok_or(()).and_then(|cookie| {
trace_!("Flash: retrieving message: {:?}", cookie);
// Parse the flash message.
let content = cookie.value();
let (len_str, kv) = match content.find(FLASH_COOKIE_DELIM) {

View File

@ -484,7 +484,7 @@ impl<'r, 'o: 'r, R: Responder<'r, 'o>> Responder<'r, 'o> for Option<R> {
match self {
Some(r) => r.respond_to(req),
None => {
warn_!("Response was `None`.");
debug!("{} responder returned `None`", std::any::type_name::<Self>());
Err(Status::NotFound)
},
}

View File

@ -789,9 +789,9 @@ impl<'r> Response<'r> {
}
/// Returns `Ok(Some(_))` if `self` contains a suitable handler for any of
/// the comma-separated protocols any of the strings in `I`. Returns
/// `Ok(None)` if `self` doesn't support any kind of upgrade. Returns
/// `Err(_)` if `protocols` is non-empty but no match was found in `self`.
/// the comma-separated protocol strings in `I`. Returns `Err(_)` if
/// `protocols` is non-empty but no match was found in `self`. If `self`
/// doesn't support any kind of upgrade, return `Ok(None)`.
pub(crate) fn search_upgrades<'a, I: Iterator<Item = &'a str>>(
&mut self,
protocols: I

View File

@ -11,6 +11,7 @@ use figment::{Figment, Provider};
use futures::TryFutureExt;
use crate::shutdown::{Stages, Shutdown};
use crate::trace::traceable::{Traceable, TraceableCollection};
use crate::{sentinel, shield::Shield, Catcher, Config, Route};
use crate::listener::{Bind, DefaultListener, Endpoint, Listener};
use crate::router::Router;
@ -562,15 +563,20 @@ impl Rocket<Build> {
self.catchers.clone().into_iter().for_each(|c| router.add_catcher(c));
router.finalize().map_err(ErrorKind::Collisions)?;
// Finally, freeze managed state.
// Finally, freeze managed state for faster access later.
self.state.freeze();
// Log everything we know: config, routes, catchers, fairings.
// TODO: Store/print managed state type names?
config.pretty_print(self.figment());
log_items("routes", self.routes(), |r| &r.uri.base, |r| &r.uri);
log_items("catchers", self.catchers(), |c| &c.base, |c| &c.base);
self.fairings.pretty_print();
let fairings = self.fairings.unique_set();
info_span!("config" [profile = %self.figment().profile()] => {
config.trace_info();
self.figment().trace_debug();
});
info_span!("routes" [count = self.routes.len()] => self.routes().trace_all_info());
info_span!("catchers" [count = self.catchers.len()] => self.catchers().trace_all_info());
info_span!("fairings" [count = fairings.len()] => fairings.trace_all_info());
// Ignite the rocket.
let rocket: Rocket<Ignite> = Rocket(Igniting {
@ -759,7 +765,7 @@ impl Rocket<Orbit> {
info_!("Forced shutdown is disabled. Runtime settings may be suboptimal.");
}
tracing::info!(target: "rocket::liftoff", endpoint = %rocket.endpoints[0]);
tracing::info!(name: "liftoff", endpoint = %rocket.endpoints[0]);
}
/// Returns the finalized, active configuration. This is guaranteed to

View File

@ -65,7 +65,9 @@ impl Route {
/// // by default, so Rocket would route the request to `b`, not `a`.
/// assert!(b.rank < a.rank);
/// ```
#[tracing::instrument(level = "trace", name = "matching", skip_all, ret)]
pub fn matches(&self, request: &Request<'_>) -> bool {
trace!(route.method = %self.method, request.method = %request.method());
self.method == request.method()
&& paths_match(self, request)
&& queries_match(self, request)
@ -139,7 +141,7 @@ impl Catcher {
}
fn paths_match(route: &Route, req: &Request<'_>) -> bool {
trace!("checking path match: route {} vs. request {}", route, req);
trace!(route.uri = %route.uri, request.uri = %req.uri());
let route_segments = &route.uri.metadata.uri_segments;
let req_segments = req.uri().path().segments();
@ -169,22 +171,25 @@ fn paths_match(route: &Route, req: &Request<'_>) -> bool {
}
fn queries_match(route: &Route, req: &Request<'_>) -> bool {
trace!("checking query match: route {} vs. request {}", route, req);
trace!(
route.query = route.uri.query().map(display),
route.query.color = route.uri.metadata.query_color.map(debug),
request.query = req.uri().query().map(display),
);
if matches!(route.uri.metadata.query_color, None | Some(Color::Wild)) {
return true;
}
let route_query_fields = route.uri.metadata.static_query_fields.iter()
.map(|(k, v)| (k.as_str(), v.as_str()));
for route_seg in route_query_fields {
let route_query_fields = route.uri.metadata.static_query_fields.iter();
for (key, val) in route_query_fields {
if let Some(query) = req.uri().query() {
if !query.segments().any(|req_seg| req_seg == route_seg) {
trace_!("request {} missing static query {:?}", req, route_seg);
if !query.segments().any(|req_seg| req_seg == (key, val)) {
debug!(key, val, request.query = %query, "missing static query");
return false;
}
} else {
trace_!("query-less request {} missing static query {:?}", req, route_seg);
debug!(key, val, "missing static query (queryless request)");
return false;
}
}
@ -193,7 +198,11 @@ fn queries_match(route: &Route, req: &Request<'_>) -> bool {
}
fn formats_match(route: &Route, req: &Request<'_>) -> bool {
trace!("checking format match: route {} vs. request {}", route, req);
trace!(
route.format = route.format.as_ref().map(display),
request.format = req.format().map(display),
);
let route_format = match route.format {
Some(ref format) => format,
None => return true,

View File

@ -17,10 +17,16 @@ use crate::error::log_server_error;
use crate::data::{IoStream, RawStream};
use crate::util::{spawn_inspect, FutureExt, ReaderStream};
use crate::http::Status;
use crate::trace::traceable::{Traceable, TraceableCollection};
type Result<T, E = crate::Error> = std::result::Result<T, E>;
impl Rocket<Orbit> {
#[tracing::instrument("request", skip_all, fields(
method = %parts.method,
uri = %parts.uri,
autohandled
))]
async fn service<T: for<'a> Into<RawStream<'a>>>(
self: Arc<Self>,
parts: http::request::Parts,
@ -32,6 +38,7 @@ impl Rocket<Orbit> {
Request::from_hyp(rocket, parts, connection).unwrap_or_else(|e| e)
});
debug_span!("request headers" => request.inner().headers().iter().trace_all_debug());
let mut response = request.into_response(
stream,
|rocket, request, data| Box::pin(rocket.preprocess(request, data)),
@ -45,10 +52,12 @@ impl Rocket<Orbit> {
).await;
// TODO: Should upgrades be handled in dispatch?
response.inner().trace_info();
debug_span!("response headers" => response.inner().headers().iter().trace_all_debug());
let io_handler = response.make_io_handler(Rocket::extract_io_handler);
if let (Some(handler), Some(upgrade)) = (io_handler, upgrade) {
if let (Some((proto, handler)), Some(upgrade)) = (io_handler, upgrade) {
let upgrade = upgrade.map_ok(IoStream::from).map_err(io::Error::other);
tokio::task::spawn(io_handler_task(upgrade, handler));
tokio::task::spawn(io_handler_task(proto, upgrade, handler));
}
let mut builder = hyper::Response::builder();
@ -73,19 +82,20 @@ impl Rocket<Orbit> {
}
}
async fn io_handler_task<S>(stream: S, mut handler: ErasedIoHandler)
#[tracing::instrument("upgrade", skip_all, fields(protocol = proto))]
async fn io_handler_task<S>(proto: String, stream: S, mut handler: ErasedIoHandler)
where S: Future<Output = io::Result<IoStream>>
{
let stream = match stream.await {
Ok(stream) => stream,
Err(e) => return warn_!("Upgrade failed: {e}"),
Err(e) => return warn!(error = %e, "i/o upgrade failed"),
};
info_!("Upgrade succeeded.");
info!("i/o upgrade succeeded");
if let Err(e) = handler.take().io(stream).await {
match e.kind() {
io::ErrorKind::BrokenPipe => warn!("Upgrade I/O handler was closed."),
e => error!("Upgrade I/O handler failed: {e}"),
io::ErrorKind::BrokenPipe => warn!("i/o handler closed"),
_ => warn!(error = %e, "i/o handler terminated unsuccessfully"),
}
}
}
@ -121,8 +131,8 @@ impl Rocket<Ignite> {
}
if cfg!(feature = "http3-preview") {
warn!("HTTP/3 cannot start without a valid TCP + TLS configuration.");
info_!("Falling back to HTTP/1 + HTTP/2 server.");
warn!("HTTP/3 cannot start without a valid TCP + TLS configuration.\n\
Falling back to HTTP/1 + HTTP/2 server.");
}
let rocket = self.into_orbit(vec![endpoint]);

View File

@ -5,6 +5,7 @@ use crate::{Rocket, Request, Response, Orbit, Config};
use crate::fairing::{Fairing, Info, Kind};
use crate::http::{Header, uncased::UncasedStr};
use crate::shield::*;
use crate::trace::traceable::*;
/// A [`Fairing`] that injects browser security and privacy headers into all
/// outgoing responses.
@ -192,15 +193,32 @@ impl Fairing for Shield {
&& rocket.figment().profile() != Config::DEBUG_PROFILE
&& !self.is_enabled::<Hsts>();
tracing::info_span!("shield", force_hsts).in_scope(|| {
for header in self.policies.values() {
info!(name: "header", name = header.name().as_str(), value = header.value());
}
info_span!("shield" [policies = self.policies.len()] => {
self.policies.values().trace_all_info();
warn!("Detected TLS-enabled liftoff without enabling HSTS.");
warn!("Shield has enabled a default HSTS policy.");
info!("To remove this warning, configure an HSTS policy.");
});
if force_hsts {
warn!("Detected TLS-enabled liftoff without enabling HSTS.");
warn!("Shield has enabled a default HSTS policy.");
info!("To remove this warning, configure an HSTS policy.");
}
})
// trace::collection_info!("shield", force_hsts => self.polices.values(), {
// warn!("Detected TLS-enabled liftoff without enabling HSTS.");
// warn!("Shield has enabled a default HSTS policy.");
// info!("To remove this warning, configure an HSTS policy.");
// });
// // tracing::info_span!("shield", force_hsts).in_scope(|| {
// // self.polices.values().trace();
// // for header in self.policies.values() {
// // info!(name: "header", name = header.name().as_str(), value = header.value());
// // }
//
// warn!("Detected TLS-enabled liftoff without enabling HSTS.");
// warn!("Shield has enabled a default HSTS policy.");
// info!("To remove this warning, configure an HSTS policy.");
// });
}
async fn on_response<'r>(&self, _: &'r Request<'_>, response: &mut Response<'r>) {

View File

@ -3,7 +3,6 @@ use std::ops::Deref;
use std::any::type_name;
use ref_cast::RefCast;
use yansi::Paint;
use crate::{Phase, Rocket, Ignite, Sentinel};
use crate::request::{self, FromRequest, Request};
@ -211,9 +210,10 @@ impl<'r, T: Send + Sync + 'static> FromRequest<'r> for &'r State<T> {
impl<T: Send + Sync + 'static> Sentinel for &State<T> {
fn abort(rocket: &Rocket<Ignite>) -> bool {
if rocket.state::<T>().is_none() {
let type_name = type_name::<T>();
error!("launching with unmanaged `{}` state.", type_name.primary().bold());
info_!("Using `State` requires managing it with `.manage()`.");
error!(type_name = type_name::<T>(),
"unmanaged state detected\n\
ensure type is being managed via `rocket.manage()`");
return true;
}

View File

@ -0,0 +1,71 @@
pub trait PaintExt: Sized {
fn emoji(self) -> yansi::Painted<Self>;
}
impl PaintExt for &str {
/// Paint::masked(), but hidden on Windows due to broken output. See #1122.
fn emoji(self) -> yansi::Painted<Self> {
#[cfg(windows)] { yansi::Paint::new("").mask() }
#[cfg(not(windows))] { yansi::Paint::new(self).mask() }
}
}
macro_rules! declare_macro {
($($name:ident $level:ident),* $(,)?) => (
$(declare_macro!([$] $name $level);)*
);
([$d:tt] $name:ident $level:ident) => (
#[macro_export]
macro_rules! $name {
($d ($t:tt)*) => ({
#[allow(unused_imports)]
use $crate::trace::macros::PaintExt as _;
$crate::tracing::$level!($d ($t)*);
})
}
);
}
declare_macro!(
// launch_meta INFO, launch_meta_ INFO,
error error, error_ error,
info info, info_ info,
trace trace, trace_ trace,
debug debug, debug_ debug,
warn warn, warn_ warn,
);
macro_rules! declare_span_macro {
($($name:ident $level:ident),* $(,)?) => (
$(declare_span_macro!([$] $name $level);)*
);
([$d:tt] $name:ident $level:ident) => (
#[macro_export]
macro_rules! $name {
($n:literal $d ([ $d ($f:tt)* ])? => $in_scope:expr) => ({
$crate::tracing::span!(tracing::Level::$level, $n $d (, $d ($f)* )?)
.in_scope(|| $in_scope);
})
}
);
}
declare_span_macro!(info_span INFO, trace_span TRACE, debug_span DEBUG);
macro_rules! event {
($level:expr, $($args:tt)*) => {{
match $level {
$crate::tracing::Level::ERROR => event!(@$crate::tracing::Level::ERROR, $($args)*),
$crate::tracing::Level::WARN => event!(@$crate::tracing::Level::WARN, $($args)*),
$crate::tracing::Level::INFO => event!(@$crate::tracing::Level::INFO, $($args)*),
$crate::tracing::Level::DEBUG => event!(@$crate::tracing::Level::DEBUG, $($args)*),
$crate::tracing::Level::TRACE => event!(@$crate::tracing::Level::TRACE, $($args)*),
}
}};
(@$level:expr, $n:expr, $($args:tt)*) => {{
$crate::tracing::event!(name: $n, target: concat!("rocket::", $n), $level, $($args)*);
}};
}

View File

@ -1,49 +1,14 @@
use rocket::Config;
#[macro_use]
pub mod macros;
#[cfg(feature = "trace")]
pub mod subscriber;
pub mod level;
pub mod traceable;
pub trait PaintExt: Sized {
fn emoji(self) -> yansi::Painted<Self>;
}
impl PaintExt for &str {
/// Paint::masked(), but hidden on Windows due to broken output. See #1122.
fn emoji(self) -> yansi::Painted<Self> {
#[cfg(windows)] { yansi::Paint::new("").mask() }
#[cfg(not(windows))] { yansi::Paint::new(self).mask() }
}
}
macro_rules! declare_macro {
($($name:ident $level:ident),* $(,)?) => (
$(declare_macro!([$] $name $level);)*
);
([$d:tt] $name:ident $level:ident) => (
#[macro_export]
macro_rules! $name {
($d ($t:tt)*) => ({
#[allow(unused_imports)]
use $crate::trace::PaintExt as _;
$crate::tracing::$level!($d ($t)*);
})
}
);
}
declare_macro!(
// launch_meta INFO, launch_meta_ INFO,
error error, error_ error,
info info, info_ info,
trace trace, trace_ trace,
debug debug, debug_ debug,
warn warn, warn_ warn,
);
pub fn init<'a, T: Into<Option<&'a Config>>>(_config: T) {
#[cfg(feature = "trace")]
subscriber::init(_config.into());
pub fn init<'a, T: Into<Option<&'a crate::Config>>>(_config: T) {
#[cfg(all(feature = "trace", debug_assertions))]
subscriber::RocketFmt::<subscriber::Pretty>::init(_config.into());
#[cfg(all(feature = "trace", not(debug_assertions)))]
subscriber::RocketFmt::<subscriber::Compact>::init(_config.into());
}

View File

@ -1,325 +0,0 @@
use std::marker::PhantomData;
use std::ops::Index;
use std::sync::OnceLock;
use std::sync::atomic::{AtomicU8, Ordering};
use std::fmt::{self, Debug, Display};
// use std::time::Instant;
use tracing::{Event, Level, Metadata, Subscriber};
use tracing::level_filters::LevelFilter;
use tracing::field::{Field, Visit};
use tracing::span::{Attributes, Id};
use tracing_subscriber::prelude::*;
use tracing_subscriber::layer::Context;
use tracing_subscriber::registry::LookupSpan;
use tracing_subscriber::{reload, filter, Layer, Registry};
use tracing_subscriber::field::RecordFields;
use figment::Source::File as RelPath;
use yansi::{Condition, Paint, Painted, Style};
use tinyvec::TinyVec;
use crate::config::{Config, CliColors};
use crate::util::Formatter;
pub trait PaintExt: Sized {
fn emoji(self) -> Painted<Self>;
}
impl PaintExt for &str {
/// Paint::masked(), but hidden on Windows due to broken output. See #1122.
fn emoji(self) -> Painted<Self> {
#[cfg(windows)] { Paint::new("").mask() }
#[cfg(not(windows))] { Paint::new(self).mask() }
}
}
pub(crate) fn init(config: Option<&Config>) {
static HANDLE: OnceLock<reload::Handle<RocketFmt<Registry>, Registry>> = OnceLock::new();
// Do nothing if there's no config and we've already initialized.
if config.is_none() && HANDLE.get().is_some() {
return;
}
let cli_colors = config.map(|c| c.cli_colors).unwrap_or(CliColors::Auto);
let log_level = config.map(|c| c.log_level).unwrap_or(Some(Level::INFO));
let (layer, reload_handle) = reload::Layer::new(RocketFmt::new(cli_colors, log_level));
let result = tracing_subscriber::registry()
.with(layer)
.try_init();
if result.is_ok() {
assert!(HANDLE.set(reload_handle).is_ok());
} if let Some(handle) = HANDLE.get() {
assert!(handle.modify(|layer| layer.set(cli_colors, log_level)).is_ok());
}
}
pub(crate) struct Data {
// start: Instant,
map: TinyVec<[(&'static str, String); 2]>,
}
impl Data {
pub fn new<T: RecordFields>(attrs: &T) -> Self {
let mut data = Data {
// start: Instant::now(),
map: TinyVec::new(),
};
attrs.record(&mut data);
data
}
pub fn get(&self, key: &str) -> Option<&str> {
self.map.iter()
.find(|(k, _)| k == &key)
.map(|(_, v)| v.as_str())
}
}
impl Index<&str> for Data {
type Output = str;
fn index(&self, index: &str) -> &Self::Output {
self.get(index).unwrap_or("[internal error: missing key]")
}
}
impl Visit for Data {
fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
self.map.push((field.name(), format!("{:?}", value)));
}
fn record_str(&mut self, field: &Field, value: &str) {
self.map.push((field.name(), value.into()));
}
}
#[derive(Default)]
struct RocketFmt<S> {
depth: AtomicU8,
filter: filter::Targets,
default_style: Style,
_subscriber: PhantomData<fn() -> S>
}
// struct Printer {
// level: Level,
// }
//
// impl Printer {
// fn print(event: &Event)
//
// }
macro_rules! log {
($this:expr, $event:expr => $fmt:expr $(, $($t:tt)*)?) => {
let metadata = $event.metadata();
let (i, s, t) = ($this.indent(), $this.style($event), metadata.target());
match *metadata.level() {
Level::WARN => print!(
concat!("{}{} ", $fmt),
i, "warning:".paint(s).yellow().bold() $(, $($t)*)?
),
Level::ERROR => print!(
concat!("{}{} ", $fmt),
i, "error:".paint(s).red().bold() $(, $($t)*)?
),
level@(Level::DEBUG | Level::TRACE) => match (metadata.file(), metadata.line()) {
(Some(f), Some(l)) => print!(
concat!("{}[{} {}{}{} {}] ", $fmt),
i, level.paint(s).bold(),
RelPath(f.into()).underline(), ":".paint(s).dim(), l, t.paint(s).dim()
$(, $($t)*)?
),
(_, _) => print!(
concat!("{}[{} {}] ", $fmt),
i, level.paint(s).bold(), t $(, $($t)*)?
),
}
_ => print!(concat!("{}", $fmt), i $(, $($t)*)?),
}
};
}
macro_rules! logln {
($this:expr, $event:expr => $fmt:literal $($t:tt)*) => {
log!($this, $event => concat!($fmt, "\n") $($t)*);
};
}
struct DisplayVisit<F>(F);
impl<F: FnMut(&Field, &dyn fmt::Display)> Visit for DisplayVisit<F> {
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
(self.0)(field, &Formatter(|f| value.fmt(f)));
}
fn record_str(&mut self, field: &Field, value: &str) {
(self.0)(field, &value)
}
}
trait DisplayFields {
fn record_display<F: FnMut(&Field, &dyn fmt::Display)>(&self, f: F);
}
impl<T: RecordFields> DisplayFields for T {
fn record_display<F: FnMut(&Field, &dyn fmt::Display)>(&self, f: F) {
self.record(&mut DisplayVisit(f));
}
}
impl<S: Subscriber + for<'a> LookupSpan<'a>> RocketFmt<S> {
fn new(cli_colors: CliColors, level: impl Into<LevelFilter>) -> Self {
let mut this = Self {
depth: AtomicU8::new(0),
filter: filter::Targets::new(),
default_style: Style::new(),
_subscriber: PhantomData,
};
this.set(cli_colors, level.into());
this
}
fn set(&mut self, cli_colors: CliColors, level: impl Into<LevelFilter>) {
self.default_style = Style::new().whenever(match cli_colors {
CliColors::Always => Condition::ALWAYS,
CliColors::Auto => Condition::DEFAULT,
CliColors::Never => Condition::NEVER,
});
self.filter = filter::Targets::new()
.with_default(level.into())
.with_target("rustls", LevelFilter::OFF)
.with_target("hyper", LevelFilter::OFF);
}
fn indent(&self) -> &'static str {
match self.depth.load(Ordering::Acquire) {
0 => "",
1 => " >> ",
2 => " >> ",
_ => " >> ",
}
}
fn style(&self, event: &Event<'_>) -> Style {
match *event.metadata().level() {
Level::ERROR => self.default_style.red(),
Level::WARN => self.default_style.yellow(),
Level::INFO => self.default_style.blue(),
Level::DEBUG => self.default_style.green(),
Level::TRACE => self.default_style.magenta(),
}
}
fn print(&self, event: &Event<'_>) {
let style = self.style(event);
let fields = event.metadata().fields();
if let Some(msg) = fields.field("message") {
event.record_display(|field: &Field, value: &dyn Display| {
if field == &msg {
log!(self, event => "{}", value.paint(style));
}
});
if fields.len() > 1 { print!(" ("); }
self.print_fields_compact(false, event);
if fields.len() > 1 { print!(")"); }
} else if !fields.is_empty() {
self.print_fields_compact(true, event);
}
if !fields.is_empty() {
println!("");
}
}
fn print_fields_compact(&self, prefix: bool, event: &Event<'_>) {
let key_style = self.style(event).bold();
let val_style = self.style(event).primary();
let mut printed = false;
event.record_display(|field: &Field, val: &dyn Display| {
let key = field.name();
if key != "message" {
if !printed && prefix {
log!(self, event => "{}: {}", key.paint(key_style), val.paint(val_style));
} else {
if printed { print!(" "); }
print!("{}: {}", key.paint(key_style), val.paint(val_style));
}
printed = true;
}
});
}
fn print_fields(&self, event: &Event<'_>) {
let style = self.style(event);
event.record_display(|key: &Field, value: &dyn Display| {
if key.name() != "message" {
logln!(self, event => "{}: {}", key.paint(style), value.paint(style).primary());
}
})
}
fn write_config(&self, event: &Event<'_>) {
// eprintln!(" > config [name = {}]", event.metadata().name());
match event.metadata().name() {
"values" => self.print_fields(event),
_ => self.print(event),
}
}
}
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for RocketFmt<S> {
fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
self.filter.would_enable(metadata.target(), metadata.level())
}
fn on_event(&self, event: &Event<'_>, ctxt: Context<'_, S>) {
// let metadata = event.metadata();
// eprintln!("[name = {}, target = {}]", metadata.name(), metadata.target());
if let Some(span) = ctxt.event_span(event) {
// eprintln!(" > [name = {}, target = {}]", span.name(), span.metadata().target());
return match span.name() {
"config" => self.write_config(event),
_ => self.print(event),
};
}
self.print(event);
}
fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
let span = ctx.span(id).expect("new_span: span does not exist");
let data = Data::new(attrs);
match span.metadata().name() {
"config" => println!("configured for {}", &data["profile"]),
name => println!("{name} {:?}", Formatter(|f| {
f.debug_map().entries(data.map.iter().map(|(k, v)| (k, v))).finish()
}))
}
span.extensions_mut().replace(data);
}
fn on_enter(&self, _: &Id, _: Context<'_, S>) {
self.depth.fetch_add(1, Ordering::AcqRel);
// let metadata = ctxt.span(id).unwrap().metadata();
// eprintln!("enter [name={}] [target={}] {:?}", metadata.name(),
// metadata.target(), metadata.fields());
}
fn on_exit(&self, _: &Id, _: Context<'_, S>) {
self.depth.fetch_sub(1, Ordering::AcqRel);
// let metadata = ctxt.span(id).unwrap().metadata();
// eprintln!("exit [name={}] [target={}] {:?}", metadata.name(),
// metadata.target(), metadata.fields());
}
}

View File

@ -0,0 +1,184 @@
use std::fmt;
use std::cell::Cell;
use std::sync::OnceLock;
use tracing::{Level, Metadata};
use tracing::field::Field;
use tracing_subscriber::prelude::*;
use tracing_subscriber::layer::Layered;
use tracing_subscriber::{reload, filter, Layer, Registry};
use tracing_subscriber::field::RecordFields;
use thread_local::ThreadLocal;
use yansi::{Condition, Paint, Style};
use crate::config::{Config, CliColors};
use crate::trace::subscriber::{RecordDisplay, RequestId, RequestIdLayer};
use crate::util::Formatter;
mod private {
pub trait FmtKind: Default + Copy + Send + Sync + 'static { }
impl FmtKind for crate::trace::subscriber::Pretty {}
impl FmtKind for crate::trace::subscriber::Compact {}
}
#[derive(Default)]
pub struct RocketFmt<K: private::FmtKind> {
state: ThreadLocal<Cell<K>>,
pub(crate) level: Option<Level>,
pub(crate) filter: filter::Targets,
pub(crate) style: Style,
}
pub type Handle<K> = reload::Handle<RocketFmt<K>, Layered<RequestIdLayer, Registry>>;
impl<K: private::FmtKind> RocketFmt<K> {
pub(crate) fn state(&self) -> K {
self.state.get_or_default().get()
}
pub(crate) fn update_state<F: FnOnce(&mut K)>(&self, update: F) {
let cell = self.state.get_or_default();
let mut old = cell.get();
update(&mut old);
cell.set(old);
}
pub(crate) fn init_with(config: Option<&Config>, handle: &OnceLock<Handle<K>>)
where Self: Layer<Layered<RequestIdLayer, Registry>>
{
// Do nothing if there's no config and we've already initialized.
if config.is_none() && handle.get().is_some() {
return;
}
let workers = config.map(|c| c.workers).unwrap_or(num_cpus::get());
let cli_colors = config.map(|c| c.cli_colors).unwrap_or(CliColors::Auto);
let log_level = config.map(|c| c.log_level).unwrap_or(Some(Level::INFO));
let formatter = RocketFmt::new(workers, cli_colors, log_level);
let (layer, reload_handle) = reload::Layer::new(formatter);
let result = tracing_subscriber::registry()
.with(RequestId::layer())
.with(layer)
.try_init();
if result.is_ok() {
assert!(handle.set(reload_handle).is_ok());
} if let Some(handle) = handle.get() {
assert!(handle.modify(|layer| layer.reset(cli_colors, log_level)).is_ok());
}
}
pub fn new(workers: usize, cli_colors: CliColors, level: Option<Level>) -> Self {
Self {
state: ThreadLocal::with_capacity(workers),
level,
filter: filter::Targets::new()
.with_default(level)
.with_target("rustls", level.filter(|&l| l == Level::TRACE))
.with_target("hyper", level.filter(|&l| l == Level::TRACE)),
style: match cli_colors {
CliColors::Always => Style::new().whenever(Condition::ALWAYS),
CliColors::Auto => Style::new().whenever(Condition::DEFAULT),
CliColors::Never => Style::new().whenever(Condition::NEVER),
}
}
}
pub fn reset(&mut self, cli_colors: CliColors, level: Option<Level>) {
let state = std::mem::take(&mut self.state);
*self = Self { state, ..Self::new(0, cli_colors, level) };
}
pub fn style(&self, metadata: &Metadata<'_>) -> Style {
match *metadata.level() {
Level::ERROR => self.style.red(),
Level::WARN => self.style.yellow(),
Level::INFO => self.style.blue(),
Level::DEBUG => self.style.green(),
Level::TRACE => self.style.magenta(),
}
}
pub fn has_message(&self, meta: &Metadata<'_>) -> bool {
meta.fields().field("message").is_some()
}
pub fn has_data_fields(&self, meta: &Metadata<'_>) -> bool {
meta.fields().iter().any(|f| f.name() != "message")
}
pub fn message<'a, F: RecordFields + 'a>(&self,
init_prefix: &'a dyn fmt::Display,
cont_prefix: &'a dyn fmt::Display,
meta: &'a Metadata<'_>,
data: F
) -> impl fmt::Display + 'a {
let style = self.style(meta);
Formatter(move |f| {
let fields = meta.fields();
let message = fields.field("message");
if let Some(message_field) = &message {
data.record_display(|field: &Field, value: &dyn fmt::Display| {
if field != message_field {
return;
}
for (i, line) in value.to_string().lines().enumerate() {
let line = line.paint(style);
if i == 0 {
let _ = writeln!(f, "{init_prefix}{line}");
} else {
let _ = writeln!(f, "{cont_prefix}{line}");
}
}
});
}
Ok(())
})
}
pub fn compact_fields<'a, F>(&self, meta: &'a Metadata<'_>, data: F) -> impl fmt::Display + 'a
where F: RecordFields + 'a
{
let key_style = self.style(meta).bold();
let val_style = self.style(meta).primary();
Formatter(move |f| {
let mut printed = false;
data.record_display(|field: &Field, val: &dyn fmt::Display| {
let key = field.name();
if key != "message" {
if printed { let _ = write!(f, " "); }
let _ = write!(f, "{}: {}", key.paint(key_style), val.paint(val_style));
printed = true;
}
});
Ok(())
})
}
pub fn print<F: RecordFields>(
&self,
prefix: &dyn fmt::Display,
cont_prefix: &dyn fmt::Display,
m: &Metadata<'_>,
data: F
) {
if self.has_message(m) {
let message = self.message(prefix, cont_prefix, m, &data);
if self.has_data_fields(m) {
println!("{message}{cont_prefix}{}", self.compact_fields(m, &data));
} else {
print!("{message}");
}
} else if self.has_data_fields(m) {
println!("{prefix}{}", self.compact_fields(m, &data));
}
}
}

View File

@ -0,0 +1,191 @@
use std::num::NonZeroU64;
use std::fmt;
use std::sync::OnceLock;
use std::time::Instant;
use time::OffsetDateTime;
use tracing::{Event, Level, Metadata, Subscriber};
use tracing::span::{Attributes, Id, Record};
use tracing_subscriber::layer::{Layer, Context};
use tracing_subscriber::registry::LookupSpan;
use tracing_subscriber::field::RecordFields;
use yansi::{Paint, Painted};
use crate::util::Formatter;
use crate::trace::subscriber::{Data, Handle, RocketFmt};
#[derive(Debug, Default, Copy, Clone)]
pub struct Compact {
/// The `tracing::Span::Id` of the request we're in, if any.
request: Option<NonZeroU64>,
}
#[derive(Debug)]
pub struct RequestData {
start: Instant,
fields: Data,
}
impl RequestData {
pub fn new<T: RecordFields>(attrs: T) -> Self {
Self {
start: Instant::now(),
fields: Data::new(attrs),
}
}
}
impl RocketFmt<Compact> {
pub fn init(config: Option<&crate::Config>) {
static HANDLE: OnceLock<Handle<Compact>> = OnceLock::new();
Self::init_with(config, &HANDLE);
}
fn request_span_id(&self) -> Option<Id> {
self.state().request.map(Id::from_non_zero_u64)
}
fn timestamp_for(&self, datetime: OffsetDateTime) -> impl fmt::Display {
Formatter(move |f| {
let (date, time) = (datetime.date(), datetime.time());
let (year, month, day) = (date.year(), date.month() as u8, date.day());
let (h, m, s, l) = (time.hour(), time.minute(), time.second(), time.millisecond());
write!(f, "{year:04}-{month:02}-{day:02}T{h:02}:{m:02}:{s:02}.{l:03}Z")
})
}
fn in_debug(&self) -> bool {
self.level.map_or(false, |l| l >= Level::DEBUG)
}
fn prefix<'a>(&self, meta: &'a Metadata<'_>) -> impl fmt::Display + 'a {
let style = self.style(meta);
let name = meta.name()
.starts_with("event ")
.then_some(meta.target())
.unwrap_or(meta.name());
let timestamp = self.timestamp_for(OffsetDateTime::now_utc());
Formatter(move |f| write!(f, "{} {:>5} {} ",
timestamp.paint(style).primary().dim(),
meta.level().paint(style),
name.paint(style).primary()))
}
fn chevron(&self, meta: &Metadata<'_>) -> Painted<&'static str> {
"".paint(self.style(meta)).bold()
}
fn print_compact<F: RecordFields>(&self, m: &Metadata<'_>, data: F) {
let style = self.style(m);
let prefix = self.prefix(m);
let chevron = self.chevron(m);
let init_prefix = Formatter(|f| write!(f, "{prefix}{chevron} "));
let cont_prefix = Formatter(|f| write!(f, "{prefix}{} ", "+".paint(style).dim()));
self.print(&init_prefix, &cont_prefix, m, data);
}
}
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for RocketFmt<Compact> {
fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
self.filter.would_enable(metadata.target(), metadata.level())
&& (self.in_debug()
|| self.request_span_id().is_none()
|| metadata.name() == "request"
|| metadata.name() == "response")
}
fn on_event(&self, event: &Event<'_>, ctxt: Context<'_, S>) {
if let Some(id) = self.request_span_id() {
if event.metadata().name() == "response" {
let req_span = ctxt.span(&id).expect("on_event: req does not exist");
let mut exts = req_span.extensions_mut();
let data = exts.get_mut::<RequestData>().unwrap();
event.record(&mut data.fields);
}
if !self.in_debug() {
return;
}
}
self.print_compact(event.metadata(), event);
}
fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("new_span: span does not exist");
if span.name() == "request" {
let data = RequestData::new(attrs);
span.extensions_mut().replace(data);
if !self.in_debug() {
return;
}
}
if self.state().request.is_none() {
self.print_compact(span.metadata(), attrs);
}
}
fn on_record(&self, id: &Id, values: &Record<'_>, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("record: span does not exist");
if self.request_span_id().as_ref() == Some(id) {
let mut extensions = span.extensions_mut();
match extensions.get_mut::<RequestData>() {
Some(data) => values.record(&mut data.fields),
None => span.extensions_mut().insert(RequestData::new(values)),
}
}
if self.in_debug() {
println!("{}{} {}",
self.prefix(span.metadata()),
self.chevron(span.metadata()),
self.compact_fields(span.metadata(), values));
}
}
fn on_enter(&self, id: &Id, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("new_span: span does not exist");
if span.name() == "request" {
self.update_state(|state| state.request = Some(id.into_non_zero_u64()));
}
}
fn on_exit(&self, id: &Id, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("new_span: span does not exist");
if span.name() == "request" {
self.update_state(|state| state.request = None);
}
}
fn on_close(&self, id: Id, ctxt: Context<'_, S>) {
let span = ctxt.span(&id).expect("new_span: span does not exist");
if span.name() == "request" {
let extensions = span.extensions();
let data = extensions.get::<RequestData>().unwrap();
let elapsed = data.start.elapsed();
let datetime = OffsetDateTime::now_utc() - elapsed;
let timestamp = self.timestamp_for(datetime);
let style = self.style(span.metadata());
let prefix = self.prefix(span.metadata());
let chevron = self.chevron(span.metadata());
println!("{prefix}{chevron} ({} {}ms) {} {} => {}",
timestamp.paint(style).primary().dim(),
elapsed.as_millis(),
&data.fields["method"].paint(style),
&data.fields["uri"],
&data.fields["status"],
);
}
}
}

View File

@ -0,0 +1,13 @@
mod visit;
mod pretty;
mod compact;
mod common;
mod request_id;
pub use visit::{RecordDisplay, Data};
pub use pretty::Pretty;
pub use compact::Compact;
pub use common::RocketFmt;
pub use request_id::{RequestId, RequestIdLayer};
pub(crate) use common::Handle;

View File

@ -0,0 +1,146 @@
use std::fmt;
use std::sync::OnceLock;
use tracing::{Event, Level, Metadata, Subscriber};
use tracing::span::{Attributes, Id, Record};
use tracing::field::Field;
use tracing_subscriber::layer::{Layer, Context};
use tracing_subscriber::registry::LookupSpan;
use tracing_subscriber::field::RecordFields;
use yansi::{Paint, Painted};
use crate::trace::subscriber::{Data, RecordDisplay, Handle, RocketFmt};
use crate::util::Formatter;
#[derive(Debug, Default, Copy, Clone)]
pub struct Pretty {
depth: u32,
}
impl RocketFmt<Pretty> {
pub fn init(config: Option<&crate::Config>) {
static HANDLE: OnceLock<Handle<Pretty>> = OnceLock::new();
Self::init_with(config, &HANDLE);
}
fn indent(&self) -> &'static str {
static INDENT: &[&str] = &["", " ", " "];
INDENT.get(self.state().depth as usize).copied().unwrap_or(" ")
}
fn marker(&self) -> &'static str {
static MARKER: &[&str] = &["", ">> ", ":: "];
MARKER.get(self.state().depth as usize).copied().unwrap_or("-- ")
}
fn emoji(&self, emoji: &'static str) -> Painted<&'static str> {
#[cfg(windows)] { "".paint(self.style).mask() }
#[cfg(not(windows))] { emoji.paint(self.style).mask() }
}
fn prefix<'a>(&self, meta: &'a Metadata<'_>) -> impl fmt::Display + 'a {
let (i, m, s) = (self.indent(), self.marker(), self.style(meta));
Formatter(move |f| match *meta.level() {
Level::WARN => write!(f, "{i}{m}{} ", "warning:".paint(s).bold()),
Level::ERROR => write!(f, "{i}{m}{} ", "error:".paint(s).bold()),
Level::INFO => write!(f, "{i}{m}"),
level => write!(f, "{i}{m}[{} {}] ", level.paint(s).bold(), meta.target()),
})
}
fn print_pretty<F: RecordFields>(&self, m: &Metadata<'_>, data: F) {
let prefix = self.prefix(m);
let cont_prefix = Formatter(|f| {
let style = self.style(m);
write!(f, "{}{} ", self.indent(), "++".paint(style).dim())
});
self.print(&prefix, &cont_prefix, m, data);
}
fn print_fields<F>(&self, metadata: &Metadata<'_>, fields: F)
where F: RecordFields
{
let style = self.style(metadata);
let prefix = self.prefix(metadata);
fields.record_display(|key: &Field, value: &dyn fmt::Display| {
if key.name() != "message" {
println!("{prefix}{}: {}", key.paint(style), value.paint(style).primary());
}
})
}
}
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for RocketFmt<Pretty> {
fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
self.filter.would_enable(metadata.target(), metadata.level())
}
fn on_event(&self, event: &Event<'_>, _: Context<'_, S>) {
let (meta, data) = (event.metadata(), Data::new(event));
let style = self.style(meta);
match meta.name() {
"config" => self.print_fields(meta, event),
"liftoff" => {
let prefix = self.prefix(meta);
println!("{prefix}{}{} {}", self.emoji("🚀 "),
"Rocket has launched from".paint(style).primary().bold(),
&data["endpoint"].paint(style).primary().bold().underline());
}
_ => self.print_pretty(meta, event),
}
}
fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctxt: Context<'_, S>) {
let data = Data::new(attrs);
let span = ctxt.span(id).expect("new_span: span does not exist");
if &data["count"] != "0" {
let name = span.name();
let icon = match name {
"config" => "🔧 ",
"routes" => "📬 ",
"catchers" => "🚧 ",
"fairings" => "📦 ",
"shield" => "🛡️ ",
"request" => "",
_ => "",
};
let meta = span.metadata();
let style = self.style(meta);
let prefix = self.prefix(meta);
let emoji = self.emoji(icon);
let name = name.paint(style).bold();
if !attrs.fields().is_empty() {
println!("{prefix}{emoji}{name} ({})", self.compact_fields(meta, attrs))
} else {
println!("{prefix}{emoji}{name}");
}
}
span.extensions_mut().replace(data);
}
fn on_record(&self, id: &Id, values: &Record<'_>, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("new_span: span does not exist");
match span.extensions_mut().get_mut::<Data>() {
Some(data) => values.record(data),
None => span.extensions_mut().insert(Data::new(values)),
}
let meta = span.metadata();
println!("{}{}", self.prefix(meta), self.compact_fields(meta, values));
}
fn on_enter(&self, _: &Id, _: Context<'_, S>) {
self.update_state(|state| state.depth = state.depth.saturating_add(1));
}
fn on_exit(&self, _: &Id, _: Context<'_, S>) {
self.update_state(|state| state.depth = state.depth.saturating_sub(1));
}
}

View File

@ -0,0 +1,136 @@
use std::fmt;
use std::hash::{Hash, Hasher};
use std::thread::ThreadId;
use std::cell::Cell;
use tracing::Subscriber;
use tracing::span::{Attributes, Id};
use tracing_subscriber::{layer::Context, Layer};
use tracing_subscriber::registry::{LookupSpan, SpanRef};
pub struct RequestIdLayer;
#[derive(Debug, Copy, Clone, Hash, PartialEq, Eq)]
pub struct RequestId(u128);
#[derive(Default)]
pub struct IdentHasher(u128);
impl RequestId {
fn new() -> Self {
thread_local! {
pub static COUNTER: Cell<u64> = Cell::new(0);
pub static THREAD_ID: Cell<Option<ThreadId>> = Cell::new(None);
}
let thread_id = THREAD_ID.get().unwrap_or_else(|| {
let id = std::thread::current().id();
THREAD_ID.set(Some(id));
id
});
let local_id = COUNTER.get();
COUNTER.set(local_id.wrapping_add(1));
let mut hasher = IdentHasher::default();
thread_id.hash(&mut hasher);
local_id.hash(&mut hasher);
RequestId(hasher.0)
}
pub fn of<R: for<'a> LookupSpan<'a>>(span: &SpanRef<'_, R>) -> Option<Self> {
span.extensions().get::<Self>().copied()
}
pub fn current() -> Option<Self> {
RequestIdLayer::current()
}
fn short(&self) -> u32 {
let mut x = ((self.0 & (0xFFFFFFFF << 48)) >> 48) as u32;
x = (x ^ (x >> 16)).wrapping_mul(0x21f0aaad);
x = (x ^ (x >> 15)).wrapping_mul(0x735a2d97);
x = x ^ (x >> 15);
x
}
pub fn layer() -> RequestIdLayer {
RequestIdLayer
}
}
impl RequestIdLayer {
thread_local! {
pub static CURRENT_REQUEST_ID: Cell<Option<RequestId>> = Cell::new(None);
}
fn current() -> Option<RequestId> {
Self::CURRENT_REQUEST_ID.get()
}
}
impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for RequestIdLayer {
fn on_new_span(&self, _: &Attributes<'_>, id: &Id, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("new_span: span does not exist");
if span.name() == "request" {
span.extensions_mut().replace(RequestId::new());
}
}
fn on_enter(&self, id: &Id, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("enter: span does not exist");
if span.name() == "request" {
Self::CURRENT_REQUEST_ID.set(RequestId::of(&span));
}
}
fn on_exit(&self, id: &Id, ctxt: Context<'_, S>) {
let span = ctxt.span(id).expect("enter: span does not exist");
if span.name() == "request" {
Self::CURRENT_REQUEST_ID.set(None);
}
}
}
impl fmt::Display for RequestId {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
fmt::Display::fmt(&self.short(), f)
}
}
impl fmt::LowerHex for RequestId {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
fmt::LowerHex::fmt(&self.short(), f)
}
}
impl fmt::UpperHex for RequestId {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
fmt::UpperHex::fmt(&self.short(), f)
}
}
impl Hasher for IdentHasher {
fn finish(&self) -> u64 {
self.0 as u64
}
fn write(&mut self, bytes: &[u8]) {
for &byte in bytes {
self.0 = (self.0 << 8) | (byte as u128);
}
}
fn write_u64(&mut self, i: u64) {
// https://github.com/skeeto/hash-prospector
fn shuffle(mut x: u64) -> u64 {
x = x.wrapping_add(1);
x = (x ^ (x >> 30)).wrapping_mul(0xbf58476d1ce4e5b9);
x = (x ^ (x >> 27)).wrapping_mul(0x94d049bb133111eb);
x = x ^ (x >> 31);
x
}
self.0 = (self.0 << 64) | shuffle(i) as u128;
}
}

View File

@ -0,0 +1,71 @@
use std::fmt;
use tinyvec::TinyVec;
use tracing::field::{Field, Visit};
use tracing_subscriber::field::RecordFields;
use crate::util::Formatter;
pub trait RecordDisplay: RecordFields {
fn record_display<F: FnMut(&Field, &dyn fmt::Display)>(&self, f: F);
}
#[derive(Debug)]
pub struct Data {
// start: Instant,
map: TinyVec<[(&'static str, String); 3]>,
}
impl Data {
pub fn new<T: RecordFields>(attrs: T) -> Self {
let mut data = Data {
// start: Instant::now(),
map: TinyVec::new(),
};
attrs.record(&mut data);
data
}
pub fn get(&self, key: &str) -> Option<&str> {
self.map.iter()
.find(|(k, _)| k == &key)
.map(|(_, v)| v.as_str())
}
}
impl std::ops::Index<&str> for Data {
type Output = str;
fn index(&self, index: &str) -> &Self::Output {
self.get(index).unwrap_or("[internal error: missing key]")
}
}
impl Visit for Data {
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
self.map.push((field.name(), format!("{:?}", value)));
}
fn record_str(&mut self, field: &Field, value: &str) {
self.map.push((field.name(), value.into()));
}
}
impl<T: RecordFields> RecordDisplay for T {
fn record_display<F: FnMut(&Field, &dyn fmt::Display)>(&self, f: F) {
struct DisplayVisit<F>(F);
impl<F: FnMut(&Field, &dyn fmt::Display)> Visit for DisplayVisit<F> {
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
(self.0)(field, &Formatter(|f| value.fmt(f)));
}
fn record_str(&mut self, field: &Field, value: &str) {
(self.0)(field, &value)
}
}
self.record(&mut DisplayVisit(f));
}
}

View File

@ -0,0 +1,239 @@
use crate::fairing::Fairing;
use crate::{route, Catcher, Config, Response, Route};
use crate::util::Formatter;
use figment::Figment;
use rocket::http::Header;
use tracing::Level;
pub trait Traceable {
fn trace(&self, level: Level);
#[inline(always)] fn trace_info(&self) { self.trace(Level::INFO) }
#[inline(always)] fn trace_warn(&self) { self.trace(Level::WARN) }
#[inline(always)] fn trace_error(&self) { self.trace(Level::ERROR) }
#[inline(always)] fn trace_debug(&self) { self.trace(Level::DEBUG) }
#[inline(always)] fn trace_trace(&self) { self.trace(Level::TRACE) }
}
pub trait TraceableCollection: Sized {
fn trace_all(self, level: Level);
#[inline(always)] fn trace_all_info(self) { self.trace_all(Level::INFO) }
#[inline(always)] fn trace_all_warn(self) { self.trace_all(Level::WARN) }
#[inline(always)] fn trace_all_error(self) { self.trace_all(Level::ERROR) }
#[inline(always)] fn trace_all_debug(self) { self.trace_all(Level::DEBUG) }
#[inline(always)] fn trace_all_trace(self) { self.trace_all(Level::TRACE) }
}
impl<T: Traceable, I: IntoIterator<Item = T>> TraceableCollection for I {
fn trace_all(self, level: Level) {
self.into_iter().for_each(|i| i.trace(level))
}
}
impl<T: Traceable> Traceable for &T {
#[inline(always)]
fn trace(&self, level: Level) {
T::trace(self, level)
}
}
impl Traceable for Figment {
fn trace(&self, level: Level) {
for param in Config::PARAMETERS {
if let Some(source) = self.find_metadata(param) {
event! { level, "figment",
param,
%source.name,
source.source = source.source.as_ref().map(display),
}
}
}
// Check for now deprecated config values.
for (key, replacement) in Config::DEPRECATED_KEYS {
if let Some(source) = self.find_metadata(key) {
event! { Level::WARN, "deprecated",
key,
replacement,
%source.name,
source.source = source.source.as_ref().map(display),
"config key `{key}` is deprecated and has no meaning"
}
}
}
}
}
impl Traceable for Config {
fn trace(&self, level: Level) {
event! { level, "config",
http2 = cfg!(feature = "http2"),
log_level = self.log_level.map(|l| l.as_str()),
cli_colors = %self.cli_colors,
workers = self.workers,
max_blocking = self.max_blocking,
ident = %self.ident,
ip_header = self.ip_header.as_ref().map(|s| s.as_str()),
proxy_proto_header = self.proxy_proto_header.as_ref().map(|s| s.as_str()),
limits = %Formatter(|f| f.debug_map()
.entries(self.limits.limits.iter().map(|(k, v)| (k.as_str(), display(v))))
.finish()),
temp_dir = %self.temp_dir.relative().display(),
keep_alive = (self.keep_alive != 0).then_some(self.keep_alive),
shutdown.ctrlc = self.shutdown.ctrlc,
shutdown.signals = %{
#[cfg(not(unix))] {
"disabled (not unix)"
}
#[cfg(unix)] {
Formatter(|f| f.debug_set()
.entries(self.shutdown.signals.iter().map(|s| s.as_str()))
.finish())
}
},
shutdown.grace = self.shutdown.grace,
shutdown.mercy = self.shutdown.mercy,
shutdown.force = self.shutdown.force,
}
#[cfg(feature = "secrets")] {
if !self.secret_key.is_provided() {
warn! {
name: "volatile_secret_key",
"secrets enabled without configuring a stable `secret_key`\n\
private/signed cookies will become unreadable after restarting\n\
disable the `secrets` feature or configure a `secret_key`\n\
this becomes a hard error in non-debug profiles",
}
}
let secret_key_is_known = Config::KNOWN_SECRET_KEYS.iter().any(|&key_str| {
let value = figment::value::Value::from(key_str);
self.secret_key == value.deserialize().expect("known key is valid")
});
if secret_key_is_known {
warn! {
name: "insecure_secret_key",
"The configured `secret_key` is exposed and insecure. \
The configured key is publicly published and thus insecure. \
Try generating a new key with `head -c64 /dev/urandom | base64`."
}
}
}
}
}
impl Traceable for Route {
fn trace(&self, level: Level) {
event! { level, "route",
name = self.name.as_ref().map(|n| &**n),
method = %self.method,
rank = self.rank,
uri = %self.uri,
uri.base = %self.uri.base(),
uri.unmounted = %self.uri.unmounted(),
format = self.format.as_ref().map(display),
}
event! { Level::DEBUG, "route",
route = self.name.as_ref().map(|n| &**n),
sentinels = %Formatter(|f| {
f.debug_set()
.entries(self.sentinels.iter().filter(|s| s.specialized).map(|s| s.type_name))
.finish()
})
}
}
}
impl Traceable for Catcher {
fn trace(&self, level: Level) {
event! { level, "catcher",
name = self.name.as_ref().map(|n| &**n),
status = %Formatter(|f| match self.code {
Some(code) => write!(f, "{}", code),
None => write!(f, "default"),
}),
rank = self.rank,
uri.base = %self.base(),
}
}
}
impl Traceable for &dyn Fairing {
fn trace(&self, level: Level) {
event!(level, "fairing", name = self.info().name, kind = %self.info().kind)
}
}
impl Traceable for figment::error::Kind {
fn trace(&self, _: Level) {
use figment::error::{OneOf as V, Kind::*};
match self {
Message(message) => error!(message),
InvalidType(actual, expected) => error!(name: "invalid type", %actual, expected),
InvalidValue(actual, expected) => error!(name: "invalid value", %actual, expected),
InvalidLength(actual, expected) => error!(name: "invalid length", %actual, expected),
UnknownVariant(actual, v) => error!(name: "unknown variant", actual, expected = %V(v)),
UnknownField(actual, v) => error!(name: "unknown field", actual, expected = %V(v)),
UnsupportedKey(actual, v) => error!(name: "unsupported key", %actual, expected = &**v),
MissingField(value) => error!(name: "missing field", value = &**value),
DuplicateField(value) => error!(name: "duplicate field", value),
ISizeOutOfRange(value) => error!(name: "out of range signed integer", value),
USizeOutOfRange(value) => error!(name: "out of range unsigned integer", value),
Unsupported(value) => error!(name: "unsupported type", %value),
}
}
}
impl Traceable for figment::Error {
fn trace(&self, _: Level) {
for e in self.clone() {
let span = tracing::error_span! {
"config",
key = (!e.path.is_empty()).then_some(&e.path).and_then(|path| {
let (profile, metadata) = (e.profile.as_ref()?, e.metadata.as_ref()?);
Some(metadata.interpolate(profile, path))
}),
source.name = e.metadata.as_ref().map(|m| &*m.name),
source.source = e.metadata.as_ref().and_then(|m| m.source.as_ref()).map(display),
};
span.in_scope(|| e.kind.trace_error());
}
}
}
impl Traceable for Header<'_> {
fn trace(&self, level: Level) {
event!(level, "header", name = self.name().as_str(), value = self.value());
}
}
impl Traceable for route::Outcome<'_> {
fn trace(&self, level: Level) {
event!(level, "outcome",
outcome = match self {
Self::Success(..) => "success",
Self::Error(..) => "error",
Self::Forward(..) => "forward",
},
status = match self {
Self::Success(r) => r.status().code,
Self::Error(s) => s.code,
Self::Forward((_, s)) => s.code,
},
)
}
}
impl Traceable for Response<'_> {
fn trace(&self, level: Level) {
event!(level, "response", status = self.status().code);
}
}

View File

@ -7,4 +7,3 @@ publish = false
[dependencies]
rocket = { path = "../../core/lib", features = ["secrets"] }
tracing-subscriber = "0.3"

View File

@ -51,7 +51,7 @@ fn wave(name: &str, age: u8) -> String {
// http://127.0.0.1:8000/?name=Rocketeer&lang=en&emoji
// http://127.0.0.1:8000/?lang=ru&emoji&name=Rocketeer
#[get("/?<lang>&<opt..>")]
fn hello(lang: Option<Lang>, opt: Options<'_>) -> String {
async fn hello(lang: Option<Lang>, opt: Options<'_>) -> String {
let mut greeting = String::new();
if opt.emoji {
greeting.push_str("👋 ");
@ -74,8 +74,6 @@ fn hello(lang: Option<Lang>, opt: Options<'_>) -> String {
#[launch]
fn rocket() -> _ {
// tracing_subscriber::fmt::init();
//
rocket::build()
.mount("/", routes![hello])
.mount("/hello", routes![world, mir])