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