Line data Source code
1 : use std::str::FromStr;
2 :
3 : use anyhow::Context;
4 : use once_cell::sync::Lazy;
5 : use strum_macros::{EnumString, EnumVariantNames};
6 :
7 1889 : #[derive(EnumString, EnumVariantNames, Eq, PartialEq, Debug, Clone, Copy)]
8 : #[strum(serialize_all = "snake_case")]
9 : pub enum LogFormat {
10 : Plain,
11 : Json,
12 : Test,
13 : }
14 :
15 : impl LogFormat {
16 895 : pub fn from_config(s: &str) -> anyhow::Result<LogFormat> {
17 895 : use strum::VariantNames;
18 895 : LogFormat::from_str(s).with_context(|| {
19 0 : format!(
20 0 : "Unrecognized log format. Please specify one of: {:?}",
21 0 : LogFormat::VARIANTS
22 0 : )
23 895 : })
24 895 : }
25 : }
26 :
27 1466 : static TRACING_EVENT_COUNT: Lazy<metrics::IntCounterVec> = Lazy::new(|| {
28 1466 : metrics::register_int_counter_vec!(
29 1466 : "libmetrics_tracing_event_count",
30 1466 : "Number of tracing events, by level",
31 1466 : &["level"]
32 1466 : )
33 1466 : .expect("failed to define metric")
34 1466 : });
35 :
36 : struct TracingEventCountLayer(&'static metrics::IntCounterVec);
37 :
38 : impl<S> tracing_subscriber::layer::Layer<S> for TracingEventCountLayer
39 : where
40 : S: tracing::Subscriber,
41 : {
42 148238 : fn on_event(
43 148238 : &self,
44 148238 : event: &tracing::Event<'_>,
45 148238 : _ctx: tracing_subscriber::layer::Context<'_, S>,
46 148238 : ) {
47 148238 : let level = event.metadata().level();
48 148238 : let level = match *level {
49 1075 : tracing::Level::ERROR => "error",
50 224 : tracing::Level::WARN => "warn",
51 146937 : tracing::Level::INFO => "info",
52 1 : tracing::Level::DEBUG => "debug",
53 1 : tracing::Level::TRACE => "trace",
54 : };
55 148238 : self.0.with_label_values(&[level]).inc();
56 148238 : }
57 : }
58 :
59 : /// Whether to add the `tracing_error` crate's `ErrorLayer`
60 : /// to the global tracing subscriber.
61 : ///
62 : pub enum TracingErrorLayerEnablement {
63 : /// Do not add the `ErrorLayer`.
64 : Disabled,
65 : /// Add the `ErrorLayer` with the filter specified by RUST_LOG, defaulting to `info` if `RUST_LOG` is unset.
66 : EnableWithRustLogFilter,
67 : }
68 :
69 1466 : pub fn init(
70 1466 : log_format: LogFormat,
71 1466 : tracing_error_layer_enablement: TracingErrorLayerEnablement,
72 1466 : ) -> anyhow::Result<()> {
73 1466 : // We fall back to printing all spans at info-level or above if
74 1466 : // the RUST_LOG environment variable is not set.
75 3508 : let rust_log_env_filter = || {
76 3508 : tracing_subscriber::EnvFilter::try_from_default_env()
77 3508 : .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info"))
78 3508 : };
79 :
80 : // NB: the order of the with() calls does not matter.
81 : // See https://docs.rs/tracing-subscriber/0.3.16/tracing_subscriber/layer/index.html#per-layer-filtering
82 : use tracing_subscriber::prelude::*;
83 1466 : let r = tracing_subscriber::registry();
84 1466 : let r = r.with({
85 1466 : let log_layer = tracing_subscriber::fmt::layer()
86 1466 : .with_target(false)
87 1466 : .with_ansi(false)
88 1466 : .with_writer(std::io::stdout);
89 1466 : let log_layer = match log_format {
90 0 : LogFormat::Json => log_layer.json().boxed(),
91 1464 : LogFormat::Plain => log_layer.boxed(),
92 2 : LogFormat::Test => log_layer.with_test_writer().boxed(),
93 : };
94 1466 : log_layer.with_filter(rust_log_env_filter())
95 1466 : });
96 1466 : let r = r.with(TracingEventCountLayer(&TRACING_EVENT_COUNT).with_filter(rust_log_env_filter()));
97 1466 : match tracing_error_layer_enablement {
98 576 : TracingErrorLayerEnablement::EnableWithRustLogFilter => r
99 576 : .with(tracing_error::ErrorLayer::default().with_filter(rust_log_env_filter()))
100 576 : .init(),
101 890 : TracingErrorLayerEnablement::Disabled => r.init(),
102 : }
103 :
104 1466 : Ok(())
105 1466 : }
106 :
107 : /// Disable the default rust panic hook by using `set_hook`.
108 : ///
109 : /// For neon binaries, the assumption is that tracing is configured before with [`init`], after
110 : /// that sentry is configured (if needed). sentry will install it's own on top of this, always
111 : /// processing the panic before we log it.
112 : ///
113 : /// When the return value is dropped, the hook is reverted to std default hook (prints to stderr).
114 : /// If the assumptions about the initialization order are not held, use
115 : /// [`TracingPanicHookGuard::forget`] but keep in mind, if tracing is stopped, then panics will be
116 : /// lost.
117 : #[must_use]
118 2142 : pub fn replace_panic_hook_with_tracing_panic_hook() -> TracingPanicHookGuard {
119 2142 : std::panic::set_hook(Box::new(tracing_panic_hook));
120 2142 : TracingPanicHookGuard::new()
121 2142 : }
122 :
123 : /// Drop guard which restores the std panic hook on drop.
124 : ///
125 : /// Tracing should not be used when it's not configured, but we cannot really latch on to any
126 : /// imaginary lifetime of tracing.
127 : pub struct TracingPanicHookGuard {
128 : act: bool,
129 : }
130 :
131 : impl TracingPanicHookGuard {
132 2142 : fn new() -> Self {
133 2142 : TracingPanicHookGuard { act: true }
134 2142 : }
135 :
136 : /// Make this hook guard not do anything when dropped.
137 2127 : pub fn forget(&mut self) {
138 2127 : self.act = false;
139 2127 : }
140 : }
141 :
142 : impl Drop for TracingPanicHookGuard {
143 2142 : fn drop(&mut self) {
144 2142 : if self.act {
145 15 : let _ = std::panic::take_hook();
146 2127 : }
147 2142 : }
148 : }
149 :
150 : /// Named symbol for our panic hook, which logs the panic.
151 1 : fn tracing_panic_hook(info: &std::panic::PanicInfo) {
152 1 : // following rust 1.66.1 std implementation:
153 1 : // https://github.com/rust-lang/rust/blob/90743e7298aca107ddaa0c202a4d3604e29bfeb6/library/std/src/panicking.rs#L235-L288
154 1 : let location = info.location();
155 :
156 1 : let msg = match info.payload().downcast_ref::<&'static str>() {
157 0 : Some(s) => *s,
158 1 : None => match info.payload().downcast_ref::<String>() {
159 1 : Some(s) => &s[..],
160 0 : None => "Box<dyn Any>",
161 : },
162 : };
163 :
164 1 : let thread = std::thread::current();
165 1 : let thread = thread.name().unwrap_or("<unnamed>");
166 1 : let backtrace = std::backtrace::Backtrace::capture();
167 :
168 1 : let _entered = if let Some(location) = location {
169 1 : tracing::error_span!("panic", %thread, location = %PrettyLocation(location))
170 : } else {
171 : // very unlikely to hit here, but the guarantees of std could change
172 0 : tracing::error_span!("panic", %thread)
173 : }
174 1 : .entered();
175 1 :
176 1 : if backtrace.status() == std::backtrace::BacktraceStatus::Captured {
177 : // this has an annoying extra '\n' in the end which anyhow doesn't do, but we cannot really
178 : // get rid of it as we cannot get in between of std::fmt::Formatter<'_>; we could format to
179 : // string, maybe even to a TLS one but tracing already does that.
180 1 : tracing::error!("{msg}\n\nStack backtrace:\n{backtrace}");
181 : } else {
182 0 : tracing::error!("{msg}");
183 : }
184 :
185 : // ensure that we log something on the panic if this hook is left after tracing has been
186 : // unconfigured. worst case when teardown is racing the panic is to log the panic twice.
187 1 : tracing::dispatcher::get_default(|d| {
188 1 : if let Some(_none) = d.downcast_ref::<tracing::subscriber::NoSubscriber>() {
189 0 : let location = location.map(PrettyLocation);
190 0 : log_panic_to_stderr(thread, msg, location, &backtrace);
191 1 : }
192 1 : });
193 1 : }
194 :
195 : #[cold]
196 0 : fn log_panic_to_stderr(
197 0 : thread: &str,
198 0 : msg: &str,
199 0 : location: Option<PrettyLocation<'_, '_>>,
200 0 : backtrace: &std::backtrace::Backtrace,
201 0 : ) {
202 0 : eprintln!("panic while tracing is unconfigured: thread '{thread}' panicked at '{msg}', {location:?}\nStack backtrace:\n{backtrace}");
203 0 : }
204 :
205 : struct PrettyLocation<'a, 'b>(&'a std::panic::Location<'b>);
206 :
207 : impl std::fmt::Display for PrettyLocation<'_, '_> {
208 1 : fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
209 1 : write!(f, "{}:{}:{}", self.0.file(), self.0.line(), self.0.column())
210 1 : }
211 : }
212 :
213 : impl std::fmt::Debug for PrettyLocation<'_, '_> {
214 0 : fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
215 0 : <Self as std::fmt::Display>::fmt(self, f)
216 0 : }
217 : }
218 :
219 : #[cfg(test)]
220 : mod tests {
221 : use metrics::{core::Opts, IntCounterVec};
222 :
223 : use super::TracingEventCountLayer;
224 :
225 1 : #[test]
226 1 : fn tracing_event_count_metric() {
227 1 : let counter_vec =
228 1 : IntCounterVec::new(Opts::new("testmetric", "testhelp"), &["level"]).unwrap();
229 1 : let counter_vec = Box::leak(Box::new(counter_vec)); // make it 'static
230 1 : let layer = TracingEventCountLayer(counter_vec);
231 1 : use tracing_subscriber::prelude::*;
232 1 :
233 1 : tracing::subscriber::with_default(tracing_subscriber::registry().with(layer), || {
234 1 : tracing::trace!("foo");
235 1 : tracing::debug!("foo");
236 1 : tracing::info!("foo");
237 1 : tracing::warn!("foo");
238 1 : tracing::error!("foo");
239 1 : });
240 1 :
241 1 : assert_eq!(counter_vec.with_label_values(&["trace"]).get(), 1);
242 1 : assert_eq!(counter_vec.with_label_values(&["debug"]).get(), 1);
243 1 : assert_eq!(counter_vec.with_label_values(&["info"]).get(), 1);
244 1 : assert_eq!(counter_vec.with_label_values(&["warn"]).get(), 1);
245 1 : assert_eq!(counter_vec.with_label_values(&["error"]).get(), 1);
246 1 : }
247 : }
|
