• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 //! A simple example demonstrating how one might implement a custom
2 //! subscriber.
3 //!
4 //! This subscriber implements a tree-structured logger similar to
5 //! the "compact" formatter in [`slog-term`]. The demo mimics the
6 //! example output in the screenshot in the [`slog` README].
7 //!
8 //! Note that this logger isn't ready for actual production use.
9 //! Several corners were cut to make the example simple.
10 //!
11 //! [`slog-term`]: https://docs.rs/slog-term/2.4.0/slog_term/
12 //! [`slog` README]: https://github.com/slog-rs/slog#terminal-output-example
13 use ansi_term::{Color, Style};
14 use tracing::{
15     field::{Field, Visit},
16     Id, Level, Subscriber,
17 };
18 
19 use std::{
20     cell::RefCell,
21     collections::HashMap,
22     fmt,
23     io::{self, Write},
24     sync::{
25         atomic::{AtomicUsize, Ordering},
26         Mutex,
27     },
28     thread,
29     time::SystemTime,
30 };
31 
32 /// Tracks the currently executing span on a per-thread basis.
33 #[derive(Clone)]
34 pub struct CurrentSpanPerThread {
35     current: &'static thread::LocalKey<RefCell<Vec<Id>>>,
36 }
37 
38 impl CurrentSpanPerThread {
new() -> Self39     pub fn new() -> Self {
40         thread_local! {
41             static CURRENT: RefCell<Vec<Id>> = RefCell::new(vec![]);
42         };
43         Self { current: &CURRENT }
44     }
45 
46     /// Returns the [`Id`](::Id) of the span in which the current thread is
47     /// executing, or `None` if it is not inside of a span.
id(&self) -> Option<Id>48     pub fn id(&self) -> Option<Id> {
49         self.current
50             .with(|current| current.borrow().last().cloned())
51     }
52 
enter(&self, span: Id)53     pub fn enter(&self, span: Id) {
54         self.current.with(|current| {
55             current.borrow_mut().push(span);
56         })
57     }
58 
exit(&self)59     pub fn exit(&self) {
60         self.current.with(|current| {
61             let _ = current.borrow_mut().pop();
62         })
63     }
64 }
65 
66 pub struct SloggishSubscriber {
67     // TODO: this can probably be unified with the "stack" that's used for
68     // printing?
69     current: CurrentSpanPerThread,
70     indent_amount: usize,
71     stderr: io::Stderr,
72     stack: Mutex<Vec<Id>>,
73     spans: Mutex<HashMap<Id, Span>>,
74     ids: AtomicUsize,
75 }
76 
77 struct Span {
78     parent: Option<Id>,
79     kvs: Vec<(&'static str, String)>,
80 }
81 
82 struct Event<'a> {
83     stderr: io::StderrLock<'a>,
84     comma: bool,
85 }
86 
87 struct ColorLevel<'a>(&'a Level);
88 
89 impl<'a> fmt::Display for ColorLevel<'a> {
fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result90     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
91         match *self.0 {
92             Level::TRACE => Color::Purple.paint("TRACE"),
93             Level::DEBUG => Color::Blue.paint("DEBUG"),
94             Level::INFO => Color::Green.paint("INFO "),
95             Level::WARN => Color::Yellow.paint("WARN "),
96             Level::ERROR => Color::Red.paint("ERROR"),
97         }
98         .fmt(f)
99     }
100 }
101 
102 impl Span {
new(parent: Option<Id>, attrs: &tracing::span::Attributes<'_>) -> Self103     fn new(parent: Option<Id>, attrs: &tracing::span::Attributes<'_>) -> Self {
104         let mut span = Self {
105             parent,
106             kvs: Vec::new(),
107         };
108         attrs.record(&mut span);
109         span
110     }
111 }
112 
113 impl Visit for Span {
record_debug(&mut self, field: &Field, value: &dyn fmt::Debug)114     fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
115         self.kvs.push((field.name(), format!("{:?}", value)))
116     }
117 }
118 
119 impl<'a> Visit for Event<'a> {
record_debug(&mut self, field: &Field, value: &dyn fmt::Debug)120     fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
121         write!(
122             &mut self.stderr,
123             "{comma} ",
124             comma = if self.comma { "," } else { "" },
125         )
126         .unwrap();
127         let name = field.name();
128         if name == "message" {
129             write!(
130                 &mut self.stderr,
131                 "{}",
132                 // Have to alloc here due to `ansi_term`'s API...
133                 Style::new().bold().paint(format!("{:?}", value))
134             )
135             .unwrap();
136         } else {
137             write!(
138                 &mut self.stderr,
139                 "{}: {:?}",
140                 Style::new().bold().paint(name),
141                 value
142             )
143             .unwrap();
144         }
145         self.comma = true;
146     }
147 }
148 
149 impl SloggishSubscriber {
new(indent_amount: usize) -> Self150     pub fn new(indent_amount: usize) -> Self {
151         Self {
152             current: CurrentSpanPerThread::new(),
153             indent_amount,
154             stderr: io::stderr(),
155             stack: Mutex::new(vec![]),
156             spans: Mutex::new(HashMap::new()),
157             ids: AtomicUsize::new(1),
158         }
159     }
160 
print_kvs<'a, I, K, V>( &self, writer: &mut impl Write, kvs: I, leading: &str, ) -> io::Result<()> where I: IntoIterator<Item = (K, V)>, K: AsRef<str> + 'a, V: fmt::Display + 'a,161     fn print_kvs<'a, I, K, V>(
162         &self,
163         writer: &mut impl Write,
164         kvs: I,
165         leading: &str,
166     ) -> io::Result<()>
167     where
168         I: IntoIterator<Item = (K, V)>,
169         K: AsRef<str> + 'a,
170         V: fmt::Display + 'a,
171     {
172         let mut kvs = kvs.into_iter();
173         if let Some((k, v)) = kvs.next() {
174             write!(
175                 writer,
176                 "{}{}: {}",
177                 leading,
178                 Style::new().bold().paint(k.as_ref()),
179                 v
180             )?;
181         }
182         for (k, v) in kvs {
183             write!(writer, ", {}: {}", Style::new().bold().paint(k.as_ref()), v)?;
184         }
185         Ok(())
186     }
187 
print_indent(&self, writer: &mut impl Write, indent: usize) -> io::Result<()>188     fn print_indent(&self, writer: &mut impl Write, indent: usize) -> io::Result<()> {
189         for _ in 0..(indent * self.indent_amount) {
190             write!(writer, " ")?;
191         }
192         Ok(())
193     }
194 }
195 
196 impl Subscriber for SloggishSubscriber {
enabled(&self, _metadata: &tracing::Metadata<'_>) -> bool197     fn enabled(&self, _metadata: &tracing::Metadata<'_>) -> bool {
198         true
199     }
200 
new_span(&self, span: &tracing::span::Attributes<'_>) -> tracing::Id201     fn new_span(&self, span: &tracing::span::Attributes<'_>) -> tracing::Id {
202         let next = self.ids.fetch_add(1, Ordering::SeqCst) as u64;
203         let id = tracing::Id::from_u64(next);
204         let span = Span::new(self.current.id(), span);
205         self.spans.lock().unwrap().insert(id.clone(), span);
206         id
207     }
208 
record(&self, span: &tracing::Id, values: &tracing::span::Record<'_>)209     fn record(&self, span: &tracing::Id, values: &tracing::span::Record<'_>) {
210         let mut spans = self.spans.lock().expect("mutex poisoned!");
211         if let Some(span) = spans.get_mut(span) {
212             values.record(span);
213         }
214     }
215 
record_follows_from(&self, _span: &tracing::Id, _follows: &tracing::Id)216     fn record_follows_from(&self, _span: &tracing::Id, _follows: &tracing::Id) {
217         // unimplemented
218     }
219 
enter(&self, span_id: &tracing::Id)220     fn enter(&self, span_id: &tracing::Id) {
221         self.current.enter(span_id.clone());
222         let mut stderr = self.stderr.lock();
223         let mut stack = self.stack.lock().unwrap();
224         let spans = self.spans.lock().unwrap();
225         let data = spans.get(span_id);
226         let parent = data.and_then(|span| span.parent.as_ref());
227         if !stack.iter().any(|id| id == span_id) {
228             let indent = if let Some(idx) = stack
229                 .iter()
230                 .position(|id| parent.map(|p| id == p).unwrap_or(false))
231             {
232                 let idx = idx + 1;
233                 stack.truncate(idx);
234                 idx
235             } else {
236                 stack.clear();
237                 0
238             };
239             self.print_indent(&mut stderr, indent).unwrap();
240             stack.push(span_id.clone());
241             if let Some(data) = data {
242                 self.print_kvs(&mut stderr, data.kvs.iter().map(|(k, v)| (k, v)), "")
243                     .unwrap();
244             }
245             writeln!(&mut stderr).unwrap();
246         }
247     }
248 
event(&self, event: &tracing::Event<'_>)249     fn event(&self, event: &tracing::Event<'_>) {
250         let mut stderr = self.stderr.lock();
251         let indent = self.stack.lock().unwrap().len();
252         self.print_indent(&mut stderr, indent).unwrap();
253         write!(
254             &mut stderr,
255             "{timestamp} {level} {target}",
256             timestamp = humantime::format_rfc3339_seconds(SystemTime::now()),
257             level = ColorLevel(event.metadata().level()),
258             target = &event.metadata().target(),
259         )
260         .unwrap();
261         let mut visitor = Event {
262             stderr,
263             comma: false,
264         };
265         event.record(&mut visitor);
266         writeln!(&mut visitor.stderr).unwrap();
267     }
268 
269     #[inline]
exit(&self, _span: &tracing::Id)270     fn exit(&self, _span: &tracing::Id) {
271         // TODO: unify stack with current span
272         self.current.exit();
273     }
274 
try_close(&self, _id: tracing::Id) -> bool275     fn try_close(&self, _id: tracing::Id) -> bool {
276         // TODO: GC unneeded spans.
277         false
278     }
279 }
280