src/reporter.rs

   1 // Copyright 2021-2022 Ian Jackson, yaahc and contributors to Hippotat and Eyre
   2 // SPDX-License-Identifier: GPL-3.0-or-later
   3 // There is NO WARRANTY.
   4
   5 use crate::prelude::*;
   6
   7 #[derive(StructOpt,Debug)]
   8 pub struct LogOpts {
   9   /// Increase debug level
  10   ///
  11   /// May be repeated for more verbosity.
  12   ///
  13   /// When using syslog, one `-D` this arranges to send to syslog even
  14   /// trace messages (mapped onto syslog level `DEBUG`);
  15   /// and two -`D` means to send to syslog even messages from lower layers
  16   /// (normally just the hippotat modules log to
  17   /// syslog).
  18   #[structopt(long, short="D", parse(from_occurrences))]
  19   debug: usize,
  20
  21   /// Syslog facility to use
  22   #[structopt(long, parse(try_from_str=parse_syslog_facility))]
  23   syslog_facility: Option<syslog::Facility>,
  24 }
  25
  26 #[throws(AE)]
  27 fn parse_syslog_facility(s: &str) -> syslog::Facility {
  28   s.parse().map_err(|()| anyhow!("unrecognised syslog facility: {:?}", s))?
  29 }
  30
  31 #[derive(Debug)]
  32 struct LogWrapper<T>{
  33   debug: usize,
  34   output: T,
  35 }
  36
  37 impl<T> LogWrapper<T> {
  38   fn wanted(&self, md: &log::Metadata<'_>) -> bool {
  39     let first = |mod_path| {
  40       let mod_path: &str = mod_path; // can't do in args as breaks lifetimes
  41       mod_path.split_once("::").map(|s| s.0).unwrap_or(mod_path)
  42     };
  43     self.debug >= 2 || first(md.target()) == first(module_path!())
  44   }
  45
  46   fn set_max_level(&self) {
  47     log::set_max_level(if self.debug < 1 {
  48       log::LevelFilter::Debug
  49     } else {
  50       log::LevelFilter::Trace
  51     });
  52   }
  53 }
  54
  55 impl<T> log::Log for LogWrapper<T> where T: log::Log {
  56   fn enabled(&self, md: &log::Metadata<'_>) -> bool {
  57     self.wanted(md) && self.output.enabled(md)
  58   }
  59
  60   fn log(&self, record: &log::Record<'_>) {
  61     if self.wanted(record.metadata()) {
  62       let mut wrap = log::Record::builder();
  63
  64       macro_rules! copy { { $( $f:ident ),* $(,)? } => {
  65         $( wrap.$f(record.$f()); )*
  66       } }
  67       copy!{
  68         level, target, module_path, file, line
  69       };
  70       match format_args!("{}: {}",
  71                          heck::AsKebabCase(record.level().as_str()),
  72                          record.args()) {
  73         args => {
  74           wrap.args(args);
  75           self.output.log(&wrap.build());
  76         }
  77       }
  78     }
  79   }
  80
  81   fn flush(&self) {
  82     self.output.flush()
  83   }
  84 }
  85
  86 impl LogOpts {
  87   #[throws(AE)]
  88   pub fn log_init(&self) {
  89     if let Some(facility) = self.syslog_facility {
  90       let f = syslog::Formatter3164 {
  91         facility,
  92         hostname: None,
  93         process: "hippotatd".into(),
  94         pid: std::process::id(),
  95       };
  96       let l = syslog::unix(f)
  97         // syslog::Error is not Sync.
  98         // https://github.com/Geal/rust-syslog/issues/65
  99         .map_err(|e| anyhow!(e.to_string()))
 100         .context("set up syslog logger")?;
 101       let l = syslog::BasicLogger::new(l);
 102       let l = LogWrapper { output: l, debug: self.debug };
 103       l.set_max_level();
 104       let l = Box::new(l) as _;
 105       log::set_boxed_logger(l).context("install syslog logger")?;
 106     } else {
 107       let env = env_logger::Env::new()
 108         .filter("HIPPOTAT_LOG")
 109         .write_style("HIPPOTAT_LOG_STYLE");
 110
 111       let mut logb = env_logger::Builder::new();
 112       logb.filter(Some("hippotat"),
 113                   *[ log::LevelFilter::Info,
 114                      log::LevelFilter::Debug ]
 115                   .get(self.debug)
 116                   .unwrap_or(
 117                     &log::LevelFilter::Trace
 118                   ));
 119       logb.parse_env(env);
 120       logb.init();
 121     }
 122   }
 123 }
 124
 125 pub struct OptionPrefixColon<T>(pub Option<T>);
 126 impl<T:Display> Display for OptionPrefixColon<T> {
 127   #[throws(fmt::Error)]
 128   fn fmt(&self, f: &mut fmt::Formatter) {
 129     if let Some(x) = &self.0 { write!(f, "{}: ", x)? }
 130   }
 131 }
 132
 133 // For clients only, really.
 134 pub struct Reporter<'r> {
 135   ic: &'r InstanceConfig,
 136   successes: u64,
 137   last_report: Option<Report>,
 138 }
 139
 140 #[derive(Debug)]
 141 struct Report {
 142   when: Instant,
 143   ok: Result<(),()>,
 144 }
 145
 146 // Reporting strategy
 147 //   - report all errors
 148 //   - report first success after a period of lack of messages
 149 //   - if error, report last success
 150
 151 impl<'r> Reporter<'r> {
 152   pub fn new(ic: &'r InstanceConfig) -> Self { Reporter {
 153     ic,
 154     successes: 0,
 155     last_report: None,
 156   } }
 157
 158   pub fn success(&mut self) {
 159     self.successes += 1;
 160     let now = Instant::now();
 161     if let Some(rep) = &self.last_report {
 162       if now - rep.when < match rep.ok {
 163         Ok(()) => match self.ic.success_report_interval {
 164           z if z == Duration::default() => return,
 165           nonzero => nonzero,
 166         },
 167         Err(()) => self.ic.effective_http_timeout,
 168       } {
 169         return
 170       }
 171     }
 172
 173     info!(target:"hippotat", "{} ({}ok): running", self.ic, self.successes);
 174     self.last_report = Some(Report { when: now, ok: Ok(()) });
 175   }
 176
 177   pub fn filter<T>(&mut self, req_num: Option<ReqNum>, r: Result<T,AE>)
 178                    -> Option<T> {
 179     let now = Instant::now();
 180     match r {
 181       Ok(t) => {
 182         Some(t)
 183       },
 184       Err(e) => {
 185         let m = (||{
 186           let mut m = self.ic.to_string();
 187           if let Some(req_num) = req_num {
 188             write!(m, " #{}", req_num)?;
 189           }
 190           if self.successes > 0 {
 191             write!(m, " ({}ok)", self.successes)?;
 192             self.successes = 0;
 193           }
 194           write!(m, ": {}", e)?;
 195           Ok::<_,fmt::Error>(m)
 196         })().unwrap();
 197         warn!(target:"hippotat", "{}", m);
 198         self.last_report = Some(Report { when: now, ok: Err(()) });
 199         None
 200       },
 201     }
 202   }
 203 }
 204
 205 use backtrace::Backtrace;
 206 use eyre::Chain;
 207 use indenter::indented;
 208
 209 #[derive(Debug)]
 210 struct EyreDedupHandler {
 211   backtrace: Option<Arc<parking_lot::Mutex<Backtrace>>>,
 212 }
 213
 214 type EyreDynError<'r> = &'r (dyn std::error::Error + 'static);
 215
 216 impl eyre::EyreHandler for EyreDedupHandler {
 217   #[throws(fmt::Error)]
 218   fn display(&self, error: EyreDynError, f: &mut fmt::Formatter) {
 219     let mut last: Option<String> = None;
 220     let mut error = Some(error);
 221     while let Some(e) = error {
 222       let m = e.to_string();
 223       match last {
 224         None => write!(f, "{}", m)?,
 225         Some(l) if l.contains(&m) => { },
 226         Some(_) => write!(f, ": {}", m)?,
 227       }
 228       last = Some(m);
 229       error = e.source();
 230     }
 231   }
 232
 233   #[throws(fmt::Error)]
 234   fn debug(&self, error: EyreDynError, f: &mut fmt::Formatter) {
 235     if f.alternate() {
 236       return core::fmt::Debug::fmt(error, f)?;
 237     }
 238
 239     write!(f, "{}", error)?;
 240
 241     if let Some(cause) = error.source() {
 242       write!(f, "\n\nCaused by:")?;
 243       let multiple = cause.source().is_some();
 244
 245       for (n, error) in Chain::new(cause).enumerate() {
 246         writeln!(f)?;
 247         if multiple {
 248           write!(indented(f).ind(n), "{}", error)?;
 249         } else {
 250           write!(indented(f), "{}", error)?;
 251         }
 252       }
 253     }
 254
 255     if let Some(bt) = &self.backtrace {
 256       let mut bt = bt.lock();
 257       bt.resolve();
 258       write!(f, "\n\nStack backtrace:\n{:?}", bt)?;
 259     }
 260   }
 261 }
 262
 263 #[throws(AE)]
 264 pub fn dedup_eyre_setup() {
 265   eyre::set_hook(Box::new(|_error| {
 266     lazy_static! {
 267       static ref BACKTRACE: bool = {
 268         match env::var("RUST_BACKTRACE") {
 269           Ok(s) if s.starts_with("1") => true,
 270           Ok(s) if s == "0" => false,
 271           Err(env::VarError::NotPresent) => false,
 272           x => {
 273             eprintln!("warning: RUST_BACKTRACE not understood: {:?}", x);
 274             false
 275           },
 276         }
 277       };
 278     }
 279     let backtrace = if *BACKTRACE {
 280       let bt = Backtrace::new_unresolved();
 281       let bt = Arc::new(bt.into());
 282       Some(bt)
 283     } else {
 284       None
 285     };
 286     Box::new(EyreDedupHandler { backtrace })
 287   }))
 288     .context("set error handler")?;
 289 }
 290
 291 const MAX_WARNINGS: usize = 15;
 292
 293 #[derive(Debug,Default)]
 294 pub struct Warnings {
 295   pub warnings: Vec<String>,
 296 }
 297
 298 #[derive(Debug,Error)]
 299 #[error("too many warnings")]
 300 pub struct TooManyWarnings;
 301
 302 impl Warnings {
 303   #[throws(TooManyWarnings)]
 304   pub fn add(&mut self, e: &dyn Display) {
 305     if self.warnings.len() >= MAX_WARNINGS { throw!(TooManyWarnings) }
 306     self.warnings.push(e.to_string());
 307   }
 308 }