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