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