Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

trace: nicer traces in tests, clean up trace configuration #766

Merged
merged 1 commit into from
Dec 10, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions Cargo.lock
Original file line number Diff line number Diff line change
Expand Up @@ -2896,9 +2896,9 @@ dependencies = [

[[package]]
name = "tracing-subscriber"
version = "0.2.14"
version = "0.2.15"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "2810660b9d5b18895d140caba6401765749a6a162e5d0736cfc44ea50db9d79d"
checksum = "a1fa8f0c8f4c594e4fc9debc1990deab13238077271ba84dd853d54902ee3401"
dependencies = [
"ansi_term",
"chrono",
Expand Down
2 changes: 1 addition & 1 deletion linkerd/app/core/src/admin/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -210,7 +210,7 @@ mod tests {
let (r, l0) = Readiness::new();
let l1 = l0.clone();

let (_, t) = trace::with_filter_and_format("", "");
let (_, t) = trace::Settings::default().build();
let admin = Admin::new((), r, t);
macro_rules! call {
() => {{
Expand Down
6 changes: 3 additions & 3 deletions linkerd/app/outbound/src/tcp/tests.rs
Original file line number Diff line number Diff line change
Expand Up @@ -762,7 +762,7 @@ async fn profile_endpoint_propagates_conn_errors() {
)
.await
.map_err(Into::into);
tracing::info!(?res);
tracing::debug!(?res);
assert_eq!(
res.unwrap_err()
.downcast_ref::<io::Error>()
Expand Down Expand Up @@ -861,13 +861,13 @@ where
Some(orig_dst),
);
let svc = new_svc.new_service(addrs);
tracing::debug!("new service");
tracing::trace!("new service");
svc
};
async move {
let io = support::io().read(b"hello\r\n").write(b"world").build();
let res = svc.oneshot(io).err_into::<Error>().await;
tracing::debug!(?res);
tracing::trace!(?res);
if let Err(err) = res {
if let Some(err) = err.downcast_ref::<std::io::Error>() {
// did the pretend server hang up, or did something
Expand Down
13 changes: 9 additions & 4 deletions linkerd/app/test/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -47,9 +47,10 @@ pub fn io() -> io::Builder {
}

/// By default, disable logging in modules that are expected to error in tests.
const DEFAULT_LOG: &'static str = "error,\
linkerd2_proxy_http=off,\
linkerd2_proxy_transport=off";
const DEFAULT_LOG: &'static str = "warn,\
linkerd=debug,\
linkerd2_proxy_http=error,\
linkerd2_proxy_transport=error";

pub fn trace_subscriber() -> (Dispatch, app_core::trace::Handle) {
use std::env;
Expand All @@ -63,7 +64,11 @@ pub fn trace_subscriber() -> (Dispatch, app_core::trace::Handle) {
// This may fail, since the global log compat layer may have been
// initialized by another test.
let _ = app_core::trace::init_log_compat();
app_core::trace::with_filter_and_format(&log_level, &log_format)
app_core::trace::Settings::default()
.filter(log_level)
.format(log_format)
.test(true)
.build()
}

pub fn trace_init() -> tracing::dispatcher::DefaultGuard {
Expand Down
2 changes: 1 addition & 1 deletion linkerd/tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@ tracing = "0.1.22"
tracing-log = "0.1"

[dependencies.tracing-subscriber]
version = "0.2.14"
version = "0.2.15"
# we don't need `chrono` time formatting or ANSI colored output
default-features = false
features = ["env-filter", "fmt", "smallvec", "tracing-log", "json", "parking_lot"]
Expand Down
28 changes: 10 additions & 18 deletions linkerd/tracing/src/level.rs
Original file line number Diff line number Diff line change
@@ -1,17 +1,17 @@
use crate::{JsonFormatter, PlainFormatter};
use hyper::{body::Buf, Body};
use linkerd2_error::Error;
use std::{io, str};
use tracing::{trace, warn};
use tracing_subscriber::{reload, EnvFilter};
use tracing_subscriber::{reload, EnvFilter, Registry};

#[derive(Clone)]
pub(crate) enum Handle {
Json(reload::Handle<EnvFilter, JsonFormatter>),
Plain(reload::Handle<EnvFilter, PlainFormatter>),
}
pub(crate) struct Handle(reload::Handle<EnvFilter, Registry>);

impl Handle {
pub(crate) fn new(handle: reload::Handle<EnvFilter, Registry>) -> Self {
Self(handle)
}

pub(crate) async fn serve(
&self,
req: http::Request<Body>,
Expand Down Expand Up @@ -60,22 +60,14 @@ impl Handle {
pub fn set_level(&self, level: impl AsRef<str>) -> Result<(), Error> {
let level = level.as_ref();
let filter = level.parse::<EnvFilter>()?;
match self {
Self::Json(level) => level.reload(filter)?,
Self::Plain(level) => level.reload(filter)?,
}
self.0.reload(filter)?;
tracing::info!(%level, "set new log level");
Ok(())
}

pub fn current(&self) -> Result<String, Error> {
match self {
Self::Json(handle) => handle
.with_current(|f| format!("{}", f))
.map_err(Into::into),
Self::Plain(handle) => handle
.with_current(|f| format!("{}", f))
.map_err(Into::into),
}
self.0
.with_current(|f| format!("{}", f))
.map_err(Into::into)
}
}
149 changes: 89 additions & 60 deletions linkerd/tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -9,25 +9,14 @@ use linkerd2_error::Error;
use std::{env, str};
use tokio_trace::tasks::TasksLayer;
use tracing::Dispatch;
use tracing_subscriber::{
fmt::{format, Layer as FmtLayer},
layer::Layered,
prelude::*,
};
use tracing_subscriber::{fmt::format, prelude::*};

const ENV_LOG_LEVEL: &str = "LINKERD2_PROXY_LOG";
const ENV_LOG_FORMAT: &str = "LINKERD2_PROXY_LOG_FORMAT";

const DEFAULT_LOG_LEVEL: &str = "warn,linkerd2_proxy=info";
const DEFAULT_LOG_FORMAT: &str = "PLAIN";

type JsonFormatter = Formatter<format::JsonFields, format::Json>;
type PlainFormatter = Formatter<format::DefaultFields, format::Full>;
type Formatter<F, E> = Layered<
FmtLayer<Layered<TasksLayer<F>, tracing_subscriber::Registry>, F, format::Format<E, Uptime>>,
Layered<TasksLayer<F>, tracing_subscriber::Registry>,
>;

/// Initialize tracing and logging with the value of the `ENV_LOG`
/// environment variable as the verbosity-level filter.
pub fn init() -> Result<Handle, Error> {
Expand All @@ -37,7 +26,10 @@ pub fn init() -> Result<Handle, Error> {
}

let log_format = env::var(ENV_LOG_FORMAT).unwrap_or(DEFAULT_LOG_FORMAT.to_string());
let (dispatch, handle) = with_filter_and_format(log_level, log_format);
let (dispatch, handle) = Settings::default()
.filter(log_level)
.format(log_format)
.build();

// Set up log compatibility.
init_log_compat()?;
Expand All @@ -51,55 +43,92 @@ pub fn init_log_compat() -> Result<(), Error> {
tracing_log::LogTracer::init().map_err(Error::from)
}

pub fn with_filter_and_format(
filter: impl AsRef<str>,
format: impl AsRef<str>,
) -> (Dispatch, Handle) {
let filter = filter.as_ref();

// Set up the subscriber
let filter = tracing_subscriber::EnvFilter::new(filter);
let formatter = tracing_subscriber::fmt::format()
.with_timer(Uptime::starting_now())
.with_thread_ids(true);

let (dispatch, level, tasks) = match format.as_ref().to_uppercase().as_ref() {
"JSON" => {
let (tasks, tasks_layer) = TasksLayer::<format::JsonFields>::new();
let (filter, level) = tracing_subscriber::reload::Layer::new(filter);
let dispatch = tracing_subscriber::registry()
.with(tasks_layer)
.with(
tracing_subscriber::fmt::layer()
.event_format(formatter)
.json()
.with_span_list(true),
)
.with(filter)
.into();
let handle = level::Handle::Json(level);
(dispatch, handle, tasks)
#[derive(Debug, Default)]
pub struct Settings {
filter: Option<String>,
format: Option<String>,
test: bool,
}

impl Settings {
pub fn from_env() -> Self {
let mut settings = Settings::default();
if let Ok(filter) = env::var(ENV_LOG_LEVEL) {
settings = settings.filter(filter);
}
if let Ok(format) = env::var(ENV_LOG_FORMAT) {
settings = settings.format(format);
}
settings
}

pub fn filter(self, filter: impl Into<String>) -> Self {
Self {
filter: Some(filter.into()),
..self
}
_ => {
let (tasks, tasks_layer) = TasksLayer::<format::DefaultFields>::new();
let (filter, level) = tracing_subscriber::reload::Layer::new(filter);
let dispatch = tracing_subscriber::registry()
.with(tasks_layer)
.with(tracing_subscriber::fmt::layer().event_format(formatter))
.with(filter)
.into();
let handle = level::Handle::Plain(level);
(dispatch, handle, tasks)
}

pub fn format(self, format: impl Into<String>) -> Self {
Self {
format: Some(format.into()),
..self
}
};

(
dispatch,
Handle(Inner::Enabled {
level,
tasks: tasks::Handle { tasks },
}),
)
}

pub fn test(self, test: bool) -> Self {
Self { test, ..self }
}

pub fn build(self) -> (Dispatch, Handle) {
let filter = self.filter.unwrap_or_else(|| DEFAULT_LOG_LEVEL.to_string());
let format = self
.format
.unwrap_or_else(|| DEFAULT_LOG_FORMAT.to_string());

// Set up the subscriber
let fmt = tracing_subscriber::fmt::format()
.with_timer(Uptime::starting_now())
.with_thread_ids(!self.test);
let filter = tracing_subscriber::EnvFilter::new(filter);
let (filter, level) = tracing_subscriber::reload::Layer::new(filter);
let level = level::Handle::new(level);
let registry = tracing_subscriber::registry().with(filter);

let (dispatch, tasks) = match format.to_uppercase().as_ref() {
"JSON" => {
let (tasks, tasks_layer) = TasksLayer::<format::JsonFields>::new();
let fmt =
tracing_subscriber::fmt::layer().event_format(fmt.json().with_span_list(true));
let registry = registry.with(tasks_layer);
let dispatch = if self.test {
registry.with(fmt.with_test_writer()).into()
} else {
registry.with(fmt).into()
};
(dispatch, tasks)
}
_ => {
let (tasks, tasks_layer) = TasksLayer::<format::DefaultFields>::new();
let registry = registry.with(tasks_layer);
let fmt = tracing_subscriber::fmt::layer().event_format(fmt);
let dispatch = if self.test {
registry.with(fmt.with_test_writer()).into()
} else {
registry.with(fmt).into()
};
(dispatch, tasks)
}
};

(
dispatch,
Handle(Inner::Enabled {
level,
tasks: tasks::Handle { tasks },
}),
)
}
}

#[derive(Clone)]
Expand Down