Skip to content

Commit

Permalink
wip: route tracing
Browse files Browse the repository at this point in the history
  • Loading branch information
SergioBenitez committed May 10, 2024
1 parent 5950018 commit 3816fe1
Show file tree
Hide file tree
Showing 11 changed files with 209 additions and 201 deletions.
2 changes: 1 addition & 1 deletion core/lib/src/config/config.rs
Original file line number Diff line number Diff line change
Expand Up @@ -435,5 +435,5 @@ 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) {
error.trace()
error.trace_error()
}
5 changes: 5 additions & 0 deletions core/lib/src/erased.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
20 changes: 12 additions & 8 deletions core/lib/src/lifecycle.rs
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
use yansi::Paint;
use futures::future::{FutureExt, Future};

use crate::trace::traceable::Traceable;
use crate::{route, Rocket, Orbit, Request, Response, Data};
use crate::data::IoHandler;
use crate::http::{Method, Status, Header};
Expand Down Expand Up @@ -96,16 +97,14 @@ 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;

// Route the request and run the user's handlers.
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);
Expand Down Expand Up @@ -181,6 +180,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>,
Expand All @@ -191,7 +195,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();
Expand All @@ -200,16 +203,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.
Expand Down
25 changes: 7 additions & 18 deletions core/lib/src/outcome.rs
Original file line number Diff line number Diff line change
Expand Up @@ -712,7 +712,7 @@ crate::export! {

impl<S, E, F> Outcome<S, E, F> {
#[inline]
fn dbg_str(&self) -> &'static str {
pub(crate) fn dbg_str(&self) -> &'static str {
match self {
Success(..) => "Success",
Error(..) => "Error",
Expand All @@ -730,27 +730,16 @@ impl<S, E, F> Outcome<S, E, F> {
}
}

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 route::Outcome<'_> {
pub(crate) fn status(&self) -> Status {
match self {
Success(r) => r.status(),
Error(s) => *s,
Forward((_, s)) => *s,
}
}
}

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())
Expand Down
12 changes: 8 additions & 4 deletions core/lib/src/request/request.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand Down
37 changes: 6 additions & 31 deletions core/lib/src/rocket.rs
Original file line number Diff line number Diff line change
Expand Up @@ -563,45 +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?
let fairings = self.fairings.unique_set();
info_span!("config" [profile = %self.figment().profile()] => {
config.trace();
self.figment().trace();
config.trace_info();
self.figment().trace_debug();
});

info_span!("routes" [count = self.routes.len()] => self.routes().trace_all());
info_span!("catchers" [count = self.catchers.len()] => self.catchers().trace_all());
info_span!("fairings" [count = fairings.len()] => fairings.trace_all());

// trace::all("routes", self.routes());
// tracing::info_span!("routes").in_scope(|| self.routes().for_each(|r| r.trace()));
// tracing::info_span!("catchers").in_scope(|| self.catchers().for_each(|c| c.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.");
// });

// tracing::info_span!("routes")
// .in_scope(|| self.routes().for_each(|r| r.trace()));
// // self.polices.values().trace();
// // for header in self.policies.values() {
// // info!(name: "header", name = header.name().as_str(), value = header.value());
// // }

// TODO: Store/print managed state type names?
// trace::collection_info!("routes" => self.routes());
// trace::collection_info!("catchers" => self.catchers());
// trace::collection_info!("fairings" => self.fairings.active_set());
// trace::collection_info!("state" => self.active_set());
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 {
Expand Down
7 changes: 7 additions & 0 deletions core/lib/src/server.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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::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,
Expand All @@ -32,6 +38,7 @@ impl Rocket<Orbit> {
Request::from_hyp(rocket, parts, connection).unwrap_or_else(|e| e)
});

debug_span!("headers" => request.inner().headers().iter().trace_all_debug());
let mut response = request.into_response(
stream,
|rocket, request, data| Box::pin(rocket.preprocess(request, data)),
Expand Down
2 changes: 1 addition & 1 deletion core/lib/src/shield/shield.rs
Original file line number Diff line number Diff line change
Expand Up @@ -194,7 +194,7 @@ impl Fairing for Shield {
&& !self.is_enabled::<Hsts>();

info_span!("shield" [policies = self.policies.len()] => {
self.policies.values().trace_all();
self.policies.values().trace_all_info();

if force_hsts {
warn!("Detected TLS-enabled liftoff without enabling HSTS.");
Expand Down
22 changes: 19 additions & 3 deletions core/lib/src/trace/macros.rs
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,6 @@ macro_rules! declare_macro {
($d ($t:tt)*) => ({
#[allow(unused_imports)]
use $crate::trace::macros::PaintExt as _;

$crate::tracing::$level!($d ($t)*);
})
}
Expand All @@ -46,10 +45,27 @@ macro_rules! declare_span_macro {
#[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);
$crate::tracing::span!(tracing::Level::$level, $n $d (, $d ($f)* )?)
.in_scope(|| $in_scope);
})
}
);
}

declare_span_macro!(info_span INFO, trace_span TRACE);
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)*);
}};
}
Loading

0 comments on commit 3816fe1

Please sign in to comment.