1 | //! A `tracing` [`Subscriber`] that uses the [`log`] crate as a backend for |
2 | //! formatting `tracing` spans and events. |
3 | //! |
4 | //! When a [`TraceLogger`] is set as the current subscriber, it will record |
5 | //! traces by emitting [`log::Record`]s that can be collected by a logger. |
6 | //! |
7 | //! **Note**: This API has been deprecated since version 0.1.1. In order to emit |
8 | //! `tracing` events as `log` records, the ["log" and "log-always" feature |
9 | //! flags][flags] on the `tracing` crate should be used instead. |
10 | //! |
11 | //! [`log`]: log |
12 | //! [`Subscriber`]: https://docs.rs/tracing/0.1.7/tracing/subscriber/trait.Subscriber.html |
13 | //! [`log::Record`]:log::Record |
14 | //! [flags]: https://docs.rs/tracing/latest/tracing/#crate-feature-flags |
15 | #![deprecated ( |
16 | since = "0.1.1" , |
17 | note = "use the `tracing` crate's \"log \" feature flag instead" |
18 | )] |
19 | use crate::AsLog; |
20 | use std::{ |
21 | cell::RefCell, |
22 | collections::HashMap, |
23 | fmt::{self, Write}, |
24 | sync::{ |
25 | atomic::{AtomicUsize, Ordering}, |
26 | Mutex, |
27 | }, |
28 | }; |
29 | use tracing_core::{ |
30 | field, |
31 | span::{self, Id}, |
32 | Event, Metadata, Subscriber, |
33 | }; |
34 | |
35 | /// A `tracing` [`Subscriber`] implementation that logs all recorded |
36 | /// trace events. |
37 | /// |
38 | /// **Note**: This API has been deprecated since version 0.1.1. In order to emit |
39 | /// `tracing` events as `log` records, the ["log" and "log-always" feature |
40 | /// flags][flags] on the `tracing` crate should be used instead. |
41 | /// |
42 | /// [`Subscriber`]: https://docs.rs/tracing/0.1.7/tracing/subscriber/trait.Subscriber.html |
43 | /// [flags]: https://docs.rs/tracing/latest/tracing/#crate-feature-flags |
44 | pub struct TraceLogger { |
45 | settings: Builder, |
46 | spans: Mutex<HashMap<Id, SpanLineBuilder>>, |
47 | next_id: AtomicUsize, |
48 | } |
49 | |
50 | thread_local! { |
51 | static CURRENT: RefCell<Vec<Id>> = RefCell::new(Vec::new()); |
52 | } |
53 | /// Configures and constructs a [`TraceLogger`]. |
54 | /// |
55 | #[derive (Debug)] |
56 | pub struct Builder { |
57 | log_span_closes: bool, |
58 | log_enters: bool, |
59 | log_exits: bool, |
60 | log_ids: bool, |
61 | parent_fields: bool, |
62 | log_parent: bool, |
63 | } |
64 | |
65 | // ===== impl TraceLogger ===== |
66 | |
67 | impl TraceLogger { |
68 | /// Returns a new `TraceLogger` with the default configuration. |
69 | pub fn new() -> Self { |
70 | Self::builder().finish() |
71 | } |
72 | |
73 | /// Returns a `Builder` for configuring a `TraceLogger`. |
74 | pub fn builder() -> Builder { |
75 | Default::default() |
76 | } |
77 | |
78 | fn from_builder(settings: Builder) -> Self { |
79 | Self { |
80 | settings, |
81 | ..Default::default() |
82 | } |
83 | } |
84 | |
85 | fn next_id(&self) -> Id { |
86 | Id::from_u64(self.next_id.fetch_add(val:1, order:Ordering::SeqCst) as u64) |
87 | } |
88 | } |
89 | |
90 | // ===== impl Builder ===== |
91 | |
92 | impl Builder { |
93 | /// Configures whether or not the [`TraceLogger`] being constructed will log |
94 | /// when a span closes. |
95 | /// |
96 | pub fn with_span_closes(self, log_span_closes: bool) -> Self { |
97 | Self { |
98 | log_span_closes, |
99 | ..self |
100 | } |
101 | } |
102 | |
103 | /// Configures whether or not the [`TraceLogger`] being constructed will |
104 | /// include the fields of parent spans when formatting events. |
105 | /// |
106 | pub fn with_parent_fields(self, parent_fields: bool) -> Self { |
107 | Self { |
108 | parent_fields, |
109 | ..self |
110 | } |
111 | } |
112 | |
113 | /// Configures whether or not the [`TraceLogger`] being constructed will log |
114 | /// when a span is entered. |
115 | /// |
116 | /// If this is set to false, fields from the current span will still be |
117 | /// recorded as context, but the actual entry will not create a log record. |
118 | /// |
119 | pub fn with_span_entry(self, log_enters: bool) -> Self { |
120 | Self { log_enters, ..self } |
121 | } |
122 | |
123 | /// Configures whether or not the [`TraceLogger`] being constructed will log |
124 | /// when a span is exited. |
125 | /// |
126 | pub fn with_span_exits(self, log_exits: bool) -> Self { |
127 | Self { log_exits, ..self } |
128 | } |
129 | |
130 | /// Configures whether or not the [`TraceLogger`] being constructed will |
131 | /// include span IDs when formatting log output. |
132 | /// |
133 | pub fn with_ids(self, log_ids: bool) -> Self { |
134 | Self { log_ids, ..self } |
135 | } |
136 | |
137 | /// Configures whether or not the [`TraceLogger`] being constructed will |
138 | /// include the names of parent spans as context when formatting events. |
139 | /// |
140 | pub fn with_parent_names(self, log_parent: bool) -> Self { |
141 | Self { log_parent, ..self } |
142 | } |
143 | |
144 | /// Complete the builder, returning a configured [`TraceLogger`]. |
145 | /// |
146 | pub fn finish(self) -> TraceLogger { |
147 | TraceLogger::from_builder(self) |
148 | } |
149 | } |
150 | |
151 | impl Default for Builder { |
152 | fn default() -> Self { |
153 | Builder { |
154 | log_span_closes: false, |
155 | parent_fields: true, |
156 | log_exits: false, |
157 | log_ids: false, |
158 | log_parent: true, |
159 | log_enters: false, |
160 | } |
161 | } |
162 | } |
163 | |
164 | impl Default for TraceLogger { |
165 | fn default() -> Self { |
166 | TraceLogger { |
167 | settings: Default::default(), |
168 | spans: Default::default(), |
169 | next_id: AtomicUsize::new(1), |
170 | } |
171 | } |
172 | } |
173 | |
174 | #[derive (Debug)] |
175 | struct SpanLineBuilder { |
176 | parent: Option<Id>, |
177 | ref_count: usize, |
178 | fields: String, |
179 | file: Option<String>, |
180 | line: Option<u32>, |
181 | module_path: Option<String>, |
182 | target: String, |
183 | level: log::Level, |
184 | name: &'static str, |
185 | } |
186 | |
187 | impl SpanLineBuilder { |
188 | fn new(parent: Option<Id>, meta: &Metadata<'_>, fields: String) -> Self { |
189 | Self { |
190 | parent, |
191 | ref_count: 1, |
192 | fields, |
193 | file: meta.file().map(String::from), |
194 | line: meta.line(), |
195 | module_path: meta.module_path().map(String::from), |
196 | target: String::from(meta.target()), |
197 | level: meta.level().as_log(), |
198 | name: meta.name(), |
199 | } |
200 | } |
201 | |
202 | fn log_meta(&self) -> log::Metadata<'_> { |
203 | log::MetadataBuilder::new() |
204 | .level(self.level) |
205 | .target(self.target.as_ref()) |
206 | .build() |
207 | } |
208 | |
209 | fn finish(self) { |
210 | let log_meta = self.log_meta(); |
211 | let logger = log::logger(); |
212 | if logger.enabled(&log_meta) { |
213 | logger.log( |
214 | &log::Record::builder() |
215 | .metadata(log_meta) |
216 | .target(self.target.as_ref()) |
217 | .module_path(self.module_path.as_ref().map(String::as_ref)) |
218 | .file(self.file.as_ref().map(String::as_ref)) |
219 | .line(self.line) |
220 | .args(format_args!("close {}; {}" , self.name, self.fields)) |
221 | .build(), |
222 | ); |
223 | } |
224 | } |
225 | } |
226 | |
227 | impl field::Visit for SpanLineBuilder { |
228 | fn record_debug(&mut self, field: &field::Field, value: &dyn fmt::Debug) { |
229 | write!(self.fields, " {}= {:?};" , field.name(), value) |
230 | .expect(msg:"write to string should never fail" ) |
231 | } |
232 | } |
233 | |
234 | impl Subscriber for TraceLogger { |
235 | fn enabled(&self, metadata: &Metadata<'_>) -> bool { |
236 | log::logger().enabled(&metadata.as_log()) |
237 | } |
238 | |
239 | fn new_span(&self, attrs: &span::Attributes<'_>) -> Id { |
240 | let id = self.next_id(); |
241 | let mut spans = self.spans.lock().unwrap(); |
242 | let mut fields = String::new(); |
243 | let parent = self.current_id(); |
244 | if self.settings.parent_fields { |
245 | let mut next_parent = parent.as_ref(); |
246 | while let Some(parent) = next_parent.and_then(|p| spans.get(p)) { |
247 | write!(&mut fields, " {}" , parent.fields).expect("write to string cannot fail" ); |
248 | next_parent = parent.parent.as_ref(); |
249 | } |
250 | } |
251 | let mut span = SpanLineBuilder::new(parent, attrs.metadata(), fields); |
252 | attrs.record(&mut span); |
253 | spans.insert(id.clone(), span); |
254 | id |
255 | } |
256 | |
257 | fn record(&self, span: &Id, values: &span::Record<'_>) { |
258 | let mut spans = self.spans.lock().unwrap(); |
259 | if let Some(span) = spans.get_mut(span) { |
260 | values.record(span); |
261 | } |
262 | } |
263 | |
264 | fn record_follows_from(&self, span: &Id, follows: &Id) { |
265 | // TODO: this should eventually track the relationship? |
266 | log::logger().log( |
267 | &log::Record::builder() |
268 | .level(log::Level::Trace) |
269 | .args(format_args!("span {:?} follows_from= {:?};" , span, follows)) |
270 | .build(), |
271 | ); |
272 | } |
273 | |
274 | fn enter(&self, id: &Id) { |
275 | let _ = CURRENT.try_with(|current| { |
276 | let mut current = current.borrow_mut(); |
277 | if current.contains(id) { |
278 | // Ignore duplicate enters. |
279 | return; |
280 | } |
281 | current.push(id.clone()); |
282 | }); |
283 | let spans = self.spans.lock().unwrap(); |
284 | if self.settings.log_enters { |
285 | if let Some(span) = spans.get(id) { |
286 | let log_meta = span.log_meta(); |
287 | let logger = log::logger(); |
288 | if logger.enabled(&log_meta) { |
289 | let current_id = self.current_id(); |
290 | let current_fields = current_id |
291 | .as_ref() |
292 | .and_then(|id| spans.get(id)) |
293 | .map(|span| span.fields.as_ref()) |
294 | .unwrap_or("" ); |
295 | if self.settings.log_ids { |
296 | logger.log( |
297 | &log::Record::builder() |
298 | .metadata(log_meta) |
299 | .target(span.target.as_ref()) |
300 | .module_path(span.module_path.as_ref().map(String::as_ref)) |
301 | .file(span.file.as_ref().map(String::as_ref)) |
302 | .line(span.line) |
303 | .args(format_args!( |
304 | "enter {}; in= {:?}; {}" , |
305 | span.name, current_id, current_fields |
306 | )) |
307 | .build(), |
308 | ); |
309 | } else { |
310 | logger.log( |
311 | &log::Record::builder() |
312 | .metadata(log_meta) |
313 | .target(span.target.as_ref()) |
314 | .module_path(span.module_path.as_ref().map(String::as_ref)) |
315 | .file(span.file.as_ref().map(String::as_ref)) |
316 | .line(span.line) |
317 | .args(format_args!("enter {}; {}" , span.name, current_fields)) |
318 | .build(), |
319 | ); |
320 | } |
321 | } |
322 | } |
323 | } |
324 | } |
325 | |
326 | fn exit(&self, id: &Id) { |
327 | let _ = CURRENT.try_with(|current| { |
328 | let mut current = current.borrow_mut(); |
329 | if current.last() == Some(id) { |
330 | current.pop() |
331 | } else { |
332 | None |
333 | } |
334 | }); |
335 | if self.settings.log_exits { |
336 | let spans = self.spans.lock().unwrap(); |
337 | if let Some(span) = spans.get(id) { |
338 | let log_meta = span.log_meta(); |
339 | let logger = log::logger(); |
340 | if logger.enabled(&log_meta) { |
341 | logger.log( |
342 | &log::Record::builder() |
343 | .metadata(log_meta) |
344 | .target(span.target.as_ref()) |
345 | .module_path(span.module_path.as_ref().map(String::as_ref)) |
346 | .file(span.file.as_ref().map(String::as_ref)) |
347 | .line(span.line) |
348 | .args(format_args!("exit {}" , span.name)) |
349 | .build(), |
350 | ); |
351 | } |
352 | } |
353 | } |
354 | } |
355 | |
356 | fn event(&self, event: &Event<'_>) { |
357 | let meta = event.metadata(); |
358 | let log_meta = meta.as_log(); |
359 | let logger = log::logger(); |
360 | if logger.enabled(&log_meta) { |
361 | let spans = self.spans.lock().unwrap(); |
362 | let current = self.current_id().and_then(|id| spans.get(&id)); |
363 | let (current_fields, parent) = current |
364 | .map(|span| { |
365 | let fields = span.fields.as_ref(); |
366 | let parent = if self.settings.log_parent { |
367 | Some(span.name) |
368 | } else { |
369 | None |
370 | }; |
371 | (fields, parent) |
372 | }) |
373 | .unwrap_or(("" , None)); |
374 | logger.log( |
375 | &log::Record::builder() |
376 | .metadata(log_meta) |
377 | .target(meta.target()) |
378 | .module_path(meta.module_path().as_ref().cloned()) |
379 | .file(meta.file().as_ref().cloned()) |
380 | .line(meta.line()) |
381 | .args(format_args!( |
382 | " {}{}{}{}" , |
383 | parent.unwrap_or("" ), |
384 | if parent.is_some() { ": " } else { "" }, |
385 | LogEvent(event), |
386 | current_fields, |
387 | )) |
388 | .build(), |
389 | ); |
390 | } |
391 | } |
392 | |
393 | fn clone_span(&self, id: &Id) -> Id { |
394 | let mut spans = self.spans.lock().unwrap(); |
395 | if let Some(span) = spans.get_mut(id) { |
396 | span.ref_count += 1; |
397 | } |
398 | id.clone() |
399 | } |
400 | |
401 | fn try_close(&self, id: Id) -> bool { |
402 | let mut spans = self.spans.lock().unwrap(); |
403 | if spans.contains_key(&id) { |
404 | if spans.get(&id).unwrap().ref_count == 1 { |
405 | let span = spans.remove(&id).unwrap(); |
406 | if self.settings.log_span_closes { |
407 | span.finish(); |
408 | } |
409 | return true; |
410 | } else { |
411 | spans.get_mut(&id).unwrap().ref_count -= 1; |
412 | } |
413 | } |
414 | false |
415 | } |
416 | } |
417 | |
418 | impl TraceLogger { |
419 | #[inline ] |
420 | fn current_id(&self) -> Option<Id> { |
421 | CURRENT |
422 | .try_with(|current: &RefCell>| current.borrow().last().map(|span: &Id| self.clone_span(id:span))) |
423 | .ok()? |
424 | } |
425 | } |
426 | |
427 | struct LogEvent<'a>(&'a Event<'a>); |
428 | |
429 | impl<'a> fmt::Display for LogEvent<'a> { |
430 | fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { |
431 | let mut has_logged: bool = false; |
432 | let mut format_fields: impl FnMut(&Field, &dyn Debug) = |field: &field::Field, value: &dyn fmt::Debug| { |
433 | let name: &str = field.name(); |
434 | let leading: &str = if has_logged { " " } else { "" }; |
435 | // TODO: handle fmt error? |
436 | let _ = if name == "message" { |
437 | write!(f, " {}{:?};" , leading, value) |
438 | } else { |
439 | write!(f, " {}{}= {:?};" , leading, name, value) |
440 | }; |
441 | has_logged = true; |
442 | }; |
443 | |
444 | self.0.record(&mut format_fields); |
445 | Ok(()) |
446 | } |
447 | } |
448 | |
449 | impl fmt::Debug for TraceLogger { |
450 | fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { |
451 | f&mut DebugStruct<'_, '_>.debug_struct("TraceLogger" ) |
452 | .field("settings" , &self.settings) |
453 | .field("spans" , &self.spans) |
454 | .field("current" , &self.current_id()) |
455 | .field(name:"next_id" , &self.next_id) |
456 | .finish() |
457 | } |
458 | } |
459 | |