Line data Source code
1 : use std::str::FromStr;
2 :
3 : use anyhow::Context;
4 : use metrics::{IntCounter, IntCounterVec};
5 : use once_cell::sync::Lazy;
6 : use strum_macros::{EnumString, VariantNames};
7 :
8 : /// Logs a critical error, similarly to `tracing::error!`. This will:
9 : ///
10 : /// * Emit an ERROR log message with prefix "CRITICAL:" and a backtrace.
11 : /// * Trigger a pageable alert (via the metric below).
12 : /// * Increment libmetrics_tracing_event_count{level="critical"}, and indirectly level="error".
13 : /// * In debug builds, panic the process.
14 : ///
15 : /// When including errors in the message, please use {err:?} to include the error cause and original
16 : /// backtrace.
17 : #[macro_export]
18 : macro_rules! critical {
19 : ($($arg:tt)*) => {{
20 : if cfg!(debug_assertions) {
21 : panic!($($arg)*);
22 : }
23 : $crate::logging::TRACING_EVENT_COUNT_METRIC.inc_critical();
24 : let backtrace = std::backtrace::Backtrace::capture();
25 : tracing::error!("CRITICAL: {}\n{backtrace}", format!($($arg)*));
26 : }};
27 : }
28 :
29 0 : #[derive(EnumString, strum_macros::Display, VariantNames, Eq, PartialEq, Debug, Clone, Copy)]
30 : #[strum(serialize_all = "snake_case")]
31 : pub enum LogFormat {
32 : Plain,
33 : Json,
34 : Test,
35 : }
36 :
37 : impl LogFormat {
38 0 : pub fn from_config(s: &str) -> anyhow::Result<LogFormat> {
39 : use strum::VariantNames;
40 0 : LogFormat::from_str(s).with_context(|| {
41 0 : format!(
42 0 : "Unrecognized log format. Please specify one of: {:?}",
43 0 : LogFormat::VARIANTS
44 0 : )
45 0 : })
46 0 : }
47 : }
48 :
49 : pub struct TracingEventCountMetric {
50 : /// CRITICAL is not a `tracing` log level. Instead, we increment it in the `critical!` macro,
51 : /// and also emit it as a regular error. These are thus double-counted, but that seems fine.
52 : critical: IntCounter,
53 : error: IntCounter,
54 : warn: IntCounter,
55 : info: IntCounter,
56 : debug: IntCounter,
57 : trace: IntCounter,
58 : }
59 :
60 540 : pub static TRACING_EVENT_COUNT_METRIC: Lazy<TracingEventCountMetric> = Lazy::new(|| {
61 540 : let vec = metrics::register_int_counter_vec!(
62 540 : "libmetrics_tracing_event_count",
63 540 : "Number of tracing events, by level",
64 540 : &["level"]
65 540 : )
66 540 : .expect("failed to define metric");
67 540 : TracingEventCountMetric::new(vec)
68 540 : });
69 :
70 : impl TracingEventCountMetric {
71 541 : fn new(vec: IntCounterVec) -> Self {
72 541 : Self {
73 541 : critical: vec.with_label_values(&["critical"]),
74 541 : error: vec.with_label_values(&["error"]),
75 541 : warn: vec.with_label_values(&["warn"]),
76 541 : info: vec.with_label_values(&["info"]),
77 541 : debug: vec.with_label_values(&["debug"]),
78 541 : trace: vec.with_label_values(&["trace"]),
79 541 : }
80 541 : }
81 :
82 : // Allow public access from `critical!` macro.
83 0 : pub fn inc_critical(&self) {
84 0 : self.critical.inc();
85 0 : }
86 :
87 49259 : fn inc_for_level(&self, level: tracing::Level) {
88 49259 : let counter = match level {
89 85 : tracing::Level::ERROR => &self.error,
90 451 : tracing::Level::WARN => &self.warn,
91 48721 : tracing::Level::INFO => &self.info,
92 1 : tracing::Level::DEBUG => &self.debug,
93 1 : tracing::Level::TRACE => &self.trace,
94 : };
95 49259 : counter.inc();
96 49259 : }
97 : }
98 :
99 : struct TracingEventCountLayer(&'static TracingEventCountMetric);
100 :
101 : impl<S> tracing_subscriber::layer::Layer<S> for TracingEventCountLayer
102 : where
103 : S: tracing::Subscriber,
104 : {
105 49259 : fn on_event(
106 49259 : &self,
107 49259 : event: &tracing::Event<'_>,
108 49259 : _ctx: tracing_subscriber::layer::Context<'_, S>,
109 49259 : ) {
110 49259 : self.0.inc_for_level(*event.metadata().level());
111 49259 : }
112 : }
113 :
114 : /// Whether to add the `tracing_error` crate's `ErrorLayer`
115 : /// to the global tracing subscriber.
116 : ///
117 : pub enum TracingErrorLayerEnablement {
118 : /// Do not add the `ErrorLayer`.
119 : Disabled,
120 : /// Add the `ErrorLayer` with the filter specified by RUST_LOG, defaulting to `info` if `RUST_LOG` is unset.
121 : EnableWithRustLogFilter,
122 : }
123 :
124 : /// Where the logging should output to.
125 : #[derive(Clone, Copy)]
126 : pub enum Output {
127 : Stdout,
128 : Stderr,
129 : }
130 :
131 540 : pub fn init(
132 540 : log_format: LogFormat,
133 540 : tracing_error_layer_enablement: TracingErrorLayerEnablement,
134 540 : output: Output,
135 540 : ) -> anyhow::Result<()> {
136 540 : // We fall back to printing all spans at info-level or above if
137 540 : // the RUST_LOG environment variable is not set.
138 1550 : let rust_log_env_filter = || {
139 1550 : tracing_subscriber::EnvFilter::try_from_default_env()
140 1550 : .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info"))
141 1550 : };
142 :
143 : // NB: the order of the with() calls does not matter.
144 : // See https://docs.rs/tracing-subscriber/0.3.16/tracing_subscriber/layer/index.html#per-layer-filtering
145 : use tracing_subscriber::prelude::*;
146 540 : let r = tracing_subscriber::registry();
147 540 : let r = r.with({
148 540 : let log_layer = tracing_subscriber::fmt::layer()
149 540 : .with_target(false)
150 540 : .with_ansi(false)
151 540 : .with_writer(move || -> Box<dyn std::io::Write> {
152 0 : match output {
153 0 : Output::Stdout => Box::new(std::io::stdout()),
154 0 : Output::Stderr => Box::new(std::io::stderr()),
155 : }
156 540 : });
157 540 : let log_layer = match log_format {
158 0 : LogFormat::Json => log_layer.json().boxed(),
159 0 : LogFormat::Plain => log_layer.boxed(),
160 540 : LogFormat::Test => log_layer.with_test_writer().boxed(),
161 : };
162 540 : log_layer.with_filter(rust_log_env_filter())
163 540 : });
164 540 : let r = r.with(
165 540 : TracingEventCountLayer(&TRACING_EVENT_COUNT_METRIC).with_filter(rust_log_env_filter()),
166 540 : );
167 540 : match tracing_error_layer_enablement {
168 470 : TracingErrorLayerEnablement::EnableWithRustLogFilter => r
169 470 : .with(tracing_error::ErrorLayer::default().with_filter(rust_log_env_filter()))
170 470 : .init(),
171 70 : TracingErrorLayerEnablement::Disabled => r.init(),
172 : }
173 :
174 540 : Ok(())
175 540 : }
176 :
177 : /// Disable the default rust panic hook by using `set_hook`.
178 : ///
179 : /// For neon binaries, the assumption is that tracing is configured before with [`init`], after
180 : /// that sentry is configured (if needed). sentry will install it's own on top of this, always
181 : /// processing the panic before we log it.
182 : ///
183 : /// When the return value is dropped, the hook is reverted to std default hook (prints to stderr).
184 : /// If the assumptions about the initialization order are not held, use
185 : /// [`TracingPanicHookGuard::forget`] but keep in mind, if tracing is stopped, then panics will be
186 : /// lost.
187 : #[must_use]
188 8 : pub fn replace_panic_hook_with_tracing_panic_hook() -> TracingPanicHookGuard {
189 8 : std::panic::set_hook(Box::new(tracing_panic_hook));
190 8 : TracingPanicHookGuard::new()
191 8 : }
192 :
193 : /// Drop guard which restores the std panic hook on drop.
194 : ///
195 : /// Tracing should not be used when it's not configured, but we cannot really latch on to any
196 : /// imaginary lifetime of tracing.
197 : pub struct TracingPanicHookGuard {
198 : act: bool,
199 : }
200 :
201 : impl TracingPanicHookGuard {
202 8 : fn new() -> Self {
203 8 : TracingPanicHookGuard { act: true }
204 8 : }
205 :
206 : /// Make this hook guard not do anything when dropped.
207 8 : pub fn forget(&mut self) {
208 8 : self.act = false;
209 8 : }
210 : }
211 :
212 : impl Drop for TracingPanicHookGuard {
213 8 : fn drop(&mut self) {
214 8 : if self.act {
215 0 : let _ = std::panic::take_hook();
216 8 : }
217 8 : }
218 : }
219 :
220 : /// Named symbol for our panic hook, which logs the panic.
221 12 : fn tracing_panic_hook(info: &std::panic::PanicHookInfo) {
222 12 : // following rust 1.66.1 std implementation:
223 12 : // https://github.com/rust-lang/rust/blob/90743e7298aca107ddaa0c202a4d3604e29bfeb6/library/std/src/panicking.rs#L235-L288
224 12 : let location = info.location();
225 :
226 12 : let msg = match info.payload().downcast_ref::<&'static str>() {
227 0 : Some(s) => *s,
228 12 : None => match info.payload().downcast_ref::<String>() {
229 12 : Some(s) => &s[..],
230 0 : None => "Box<dyn Any>",
231 : },
232 : };
233 :
234 12 : let thread = std::thread::current();
235 12 : let thread = thread.name().unwrap_or("<unnamed>");
236 12 : let backtrace = std::backtrace::Backtrace::capture();
237 :
238 12 : let _entered = if let Some(location) = location {
239 12 : tracing::error_span!("panic", %thread, location = %PrettyLocation(location))
240 : } else {
241 : // very unlikely to hit here, but the guarantees of std could change
242 0 : tracing::error_span!("panic", %thread)
243 : }
244 12 : .entered();
245 12 :
246 12 : if backtrace.status() == std::backtrace::BacktraceStatus::Captured {
247 : // this has an annoying extra '\n' in the end which anyhow doesn't do, but we cannot really
248 : // get rid of it as we cannot get in between of std::fmt::Formatter<'_>; we could format to
249 : // string, maybe even to a TLS one but tracing already does that.
250 12 : tracing::error!("{msg}\n\nStack backtrace:\n{backtrace}");
251 : } else {
252 0 : tracing::error!("{msg}");
253 : }
254 :
255 : // ensure that we log something on the panic if this hook is left after tracing has been
256 : // unconfigured. worst case when teardown is racing the panic is to log the panic twice.
257 12 : tracing::dispatcher::get_default(|d| {
258 12 : if let Some(_none) = d.downcast_ref::<tracing::subscriber::NoSubscriber>() {
259 0 : let location = location.map(PrettyLocation);
260 0 : log_panic_to_stderr(thread, msg, location, &backtrace);
261 12 : }
262 12 : });
263 12 : }
264 :
265 : #[cold]
266 0 : fn log_panic_to_stderr(
267 0 : thread: &str,
268 0 : msg: &str,
269 0 : location: Option<PrettyLocation<'_, '_>>,
270 0 : backtrace: &std::backtrace::Backtrace,
271 0 : ) {
272 0 : eprintln!("panic while tracing is unconfigured: thread '{thread}' panicked at '{msg}', {location:?}\nStack backtrace:\n{backtrace}");
273 0 : }
274 :
275 : struct PrettyLocation<'a, 'b>(&'a std::panic::Location<'b>);
276 :
277 : impl std::fmt::Display for PrettyLocation<'_, '_> {
278 12 : fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
279 12 : write!(f, "{}:{}:{}", self.0.file(), self.0.line(), self.0.column())
280 12 : }
281 : }
282 :
283 : impl std::fmt::Debug for PrettyLocation<'_, '_> {
284 0 : fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
285 0 : <Self as std::fmt::Display>::fmt(self, f)
286 0 : }
287 : }
288 :
289 : /// When you will store a secret but want to make sure it won't
290 : /// be accidentally logged, wrap it in a SecretString, whose Debug
291 : /// implementation does not expose the contents.
292 : #[derive(Clone, Eq, PartialEq)]
293 : pub struct SecretString(String);
294 :
295 : impl SecretString {
296 0 : pub fn get_contents(&self) -> &str {
297 0 : self.0.as_str()
298 0 : }
299 : }
300 :
301 : impl From<String> for SecretString {
302 0 : fn from(s: String) -> Self {
303 0 : Self(s)
304 0 : }
305 : }
306 :
307 : impl FromStr for SecretString {
308 : type Err = std::convert::Infallible;
309 :
310 0 : fn from_str(s: &str) -> Result<Self, Self::Err> {
311 0 : Ok(Self(s.to_string()))
312 0 : }
313 : }
314 :
315 : impl std::fmt::Debug for SecretString {
316 0 : fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
317 0 : write!(f, "[SECRET]")
318 0 : }
319 : }
320 :
321 : #[cfg(test)]
322 : mod tests {
323 : use metrics::{core::Opts, IntCounterVec};
324 :
325 : use crate::logging::{TracingEventCountLayer, TracingEventCountMetric};
326 :
327 : #[test]
328 1 : fn tracing_event_count_metric() {
329 1 : let counter_vec =
330 1 : IntCounterVec::new(Opts::new("testmetric", "testhelp"), &["level"]).unwrap();
331 1 : let metric = Box::leak(Box::new(TracingEventCountMetric::new(counter_vec.clone())));
332 1 : let layer = TracingEventCountLayer(metric);
333 : use tracing_subscriber::prelude::*;
334 :
335 1 : tracing::subscriber::with_default(tracing_subscriber::registry().with(layer), || {
336 1 : tracing::trace!("foo");
337 1 : tracing::debug!("foo");
338 1 : tracing::info!("foo");
339 1 : tracing::warn!("foo");
340 1 : tracing::error!("foo");
341 1 : });
342 1 :
343 1 : assert_eq!(counter_vec.with_label_values(&["trace"]).get(), 1);
344 1 : assert_eq!(counter_vec.with_label_values(&["debug"]).get(), 1);
345 1 : assert_eq!(counter_vec.with_label_values(&["info"]).get(), 1);
346 1 : assert_eq!(counter_vec.with_label_values(&["warn"]).get(), 1);
347 1 : assert_eq!(counter_vec.with_label_values(&["error"]).get(), 1);
348 1 : }
349 : }
|
