TLA 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 CBC 1822 : #[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 858 : pub fn from_config(s: &str) -> anyhow::Result<LogFormat> {
17 858 : use strum::VariantNames;
18 858 : LogFormat::from_str(s).with_context(|| {
19 UBC 0 : format!(
20 0 : "Unrecognized log format. Please specify one of: {:?}",
21 0 : LogFormat::VARIANTS
22 0 : )
23 CBC 858 : })
24 858 : }
25 : }
26 :
27 1415 : static TRACING_EVENT_COUNT: Lazy<metrics::IntCounterVec> = Lazy::new(|| {
28 1415 : metrics::register_int_counter_vec!(
29 1415 : "libmetrics_tracing_event_count",
30 1415 : "Number of tracing events, by level",
31 1415 : &["level"]
32 1415 : )
33 1415 : .expect("failed to define metric")
34 1415 : });
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 195644 : fn on_event(
43 195644 : &self,
44 195644 : event: &tracing::Event<'_>,
45 195644 : _ctx: tracing_subscriber::layer::Context<'_, S>,
46 195644 : ) {
47 195644 : let level = event.metadata().level();
48 195644 : let level = match *level {
49 342 : tracing::Level::ERROR => "error",
50 18606 : tracing::Level::WARN => "warn",
51 176694 : tracing::Level::INFO => "info",
52 1 : tracing::Level::DEBUG => "debug",
53 1 : tracing::Level::TRACE => "trace",
54 : };
55 195644 : self.0.with_label_values(&[level]).inc();
56 195644 : }
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 1415 : pub fn init(
70 1415 : log_format: LogFormat,
71 1415 : tracing_error_layer_enablement: TracingErrorLayerEnablement,
72 1415 : ) -> anyhow::Result<()> {
73 1415 : // We fall back to printing all spans at info-level or above if
74 1415 : // the RUST_LOG environment variable is not set.
75 3391 : let rust_log_env_filter = || {
76 3391 : tracing_subscriber::EnvFilter::try_from_default_env()
77 3391 : .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info"))
78 3391 : };
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 1415 : let r = tracing_subscriber::registry();
84 1415 : let r = r.with({
85 1415 : let log_layer = tracing_subscriber::fmt::layer()
86 1415 : .with_target(false)
87 1415 : .with_ansi(false)
88 1415 : .with_writer(std::io::stdout);
89 1415 : let log_layer = match log_format {
90 UBC 0 : LogFormat::Json => log_layer.json().boxed(),
91 CBC 1412 : LogFormat::Plain => log_layer.boxed(),
92 3 : LogFormat::Test => log_layer.with_test_writer().boxed(),
93 : };
94 1415 : log_layer.with_filter(rust_log_env_filter())
95 1415 : });
96 1415 : let r = r.with(TracingEventCountLayer(&TRACING_EVENT_COUNT).with_filter(rust_log_env_filter()));
97 1415 : match tracing_error_layer_enablement {
98 561 : TracingErrorLayerEnablement::EnableWithRustLogFilter => r
99 561 : .with(tracing_error::ErrorLayer::default().with_filter(rust_log_env_filter()))
100 561 : .init(),
101 854 : TracingErrorLayerEnablement::Disabled => r.init(),
102 : }
103 :
104 1415 : Ok(())
105 1415 : }
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 2070 : pub fn replace_panic_hook_with_tracing_panic_hook() -> TracingPanicHookGuard {
119 2070 : std::panic::set_hook(Box::new(tracing_panic_hook));
120 2070 : TracingPanicHookGuard::new()
121 2070 : }
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 2070 : fn new() -> Self {
133 2070 : TracingPanicHookGuard { act: true }
134 2070 : }
135 :
136 : /// Make this hook guard not do anything when dropped.
137 2053 : pub fn forget(&mut self) {
138 2053 : self.act = false;
139 2053 : }
140 : }
141 :
142 : impl Drop for TracingPanicHookGuard {
143 2070 : fn drop(&mut self) {
144 2070 : if self.act {
145 17 : let _ = std::panic::take_hook();
146 2053 : }
147 2070 : }
148 : }
149 :
150 : /// Named symbol for our panic hook, which logs the panic.
151 2 : fn tracing_panic_hook(info: &std::panic::PanicInfo) {
152 2 : // following rust 1.66.1 std implementation:
153 2 : // https://github.com/rust-lang/rust/blob/90743e7298aca107ddaa0c202a4d3604e29bfeb6/library/std/src/panicking.rs#L235-L288
154 2 : let location = info.location();
155 :
156 2 : let msg = match info.payload().downcast_ref::<&'static str>() {
157 UBC 0 : Some(s) => *s,
158 CBC 2 : None => match info.payload().downcast_ref::<String>() {
159 2 : Some(s) => &s[..],
160 UBC 0 : None => "Box<dyn Any>",
161 : },
162 : };
163 :
164 CBC 2 : let thread = std::thread::current();
165 2 : let thread = thread.name().unwrap_or("<unnamed>");
166 2 : let backtrace = std::backtrace::Backtrace::capture();
167 :
168 2 : let _entered = if let Some(location) = location {
169 2 : tracing::error_span!("panic", %thread, location = %PrettyLocation(location))
170 : } else {
171 : // very unlikely to hit here, but the guarantees of std could change
172 UBC 0 : tracing::error_span!("panic", %thread)
173 : }
174 CBC 2 : .entered();
175 2 :
176 2 : 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 2 : tracing::error!("{msg}\n\nStack backtrace:\n{backtrace}");
181 : } else {
182 UBC 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 CBC 2 : tracing::dispatcher::get_default(|d| {
188 2 : if let Some(_none) = d.downcast_ref::<tracing::subscriber::NoSubscriber>() {
189 UBC 0 : let location = location.map(PrettyLocation);
190 0 : log_panic_to_stderr(thread, msg, location, &backtrace);
191 CBC 2 : }
192 2 : });
193 2 : }
194 :
195 : #[cold]
196 UBC 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 CBC 2 : fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
209 2 : write!(f, "{}:{}:{}", self.0.file(), self.0.line(), self.0.column())
210 2 : }
211 : }
212 :
213 : impl std::fmt::Debug for PrettyLocation<'_, '_> {
214 UBC 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 : /// When you will store a secret but want to make sure it won't
220 : /// be accidentally logged, wrap it in a SecretString, whose Debug
221 : /// implementation does not expose the contents.
222 0 : #[derive(Clone, Eq, PartialEq)]
223 : pub struct SecretString(String);
224 :
225 : impl SecretString {
226 0 : pub fn get_contents(&self) -> &str {
227 0 : self.0.as_str()
228 0 : }
229 : }
230 :
231 : impl From<String> for SecretString {
232 0 : fn from(s: String) -> Self {
233 0 : Self(s)
234 0 : }
235 : }
236 :
237 : impl std::fmt::Debug for SecretString {
238 0 : fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
239 0 : write!(f, "[SECRET]")
240 0 : }
241 : }
242 :
243 : #[cfg(test)]
244 : mod tests {
245 : use metrics::{core::Opts, IntCounterVec};
246 :
247 : use super::TracingEventCountLayer;
248 :
249 CBC 1 : #[test]
250 1 : fn tracing_event_count_metric() {
251 1 : let counter_vec =
252 1 : IntCounterVec::new(Opts::new("testmetric", "testhelp"), &["level"]).unwrap();
253 1 : let counter_vec = Box::leak(Box::new(counter_vec)); // make it 'static
254 1 : let layer = TracingEventCountLayer(counter_vec);
255 1 : use tracing_subscriber::prelude::*;
256 1 :
257 1 : tracing::subscriber::with_default(tracing_subscriber::registry().with(layer), || {
258 1 : tracing::trace!("foo");
259 1 : tracing::debug!("foo");
260 1 : tracing::info!("foo");
261 1 : tracing::warn!("foo");
262 1 : tracing::error!("foo");
263 1 : });
264 1 :
265 1 : assert_eq!(counter_vec.with_label_values(&["trace"]).get(), 1);
266 1 : assert_eq!(counter_vec.with_label_values(&["debug"]).get(), 1);
267 1 : assert_eq!(counter_vec.with_label_values(&["info"]).get(), 1);
268 1 : assert_eq!(counter_vec.with_label_values(&["warn"]).get(), 1);
269 1 : assert_eq!(counter_vec.with_label_values(&["error"]).get(), 1);
270 1 : }
271 : }
|
