rhg: Add support for the blackbox extension

Only `command` and `commandfinish` events are logged.
The `dirty`, `logsource`, `track` and `ignore` configuration items
are not supported yet.

To indicate commands executed without Python, a `(rust) ` prefix is added
in corresponding log messages.

Differential Revision: https://phab.mercurial-scm.org/D10012

rust/rhg/src/blackbox.rs

@@ -0,0 +1,161 b''
+//! Logging for repository events, including commands run in the repository.
+
+use crate::CliInvocation;
+use format_bytes::format_bytes;
+use hg::errors::HgError;
+use hg::repo::Repo;
+use hg::utils::{files::get_bytes_from_os_str, shell_quote};
+
+const ONE_MEBIBYTE: u64 = 1 << 20;
+
+// TODO: somehow keep defaults in sync with `configitem` in `hgext/blackbox.py`
+const DEFAULT_MAX_SIZE: u64 = ONE_MEBIBYTE;
+const DEFAULT_MAX_FILES: u32 = 7;
+
+// Python does not support %.3f, only %f
+const DEFAULT_DATE_FORMAT: &str = "%Y/%m/%d %H:%M:%S%.3f";
+
+type DateTime = chrono::DateTime<chrono::Local>;
+
+pub struct ProcessStartTime {
+    /// For measuring duration
+    monotonic_clock: std::time::Instant,
+    /// For formatting with year, month, day, etc.
+    calendar_based: DateTime,
+}
+
+impl ProcessStartTime {
+    pub fn now() -> Self {
+        Self {
+            monotonic_clock: std::time::Instant::now(),
+            calendar_based: chrono::Local::now(),
+        }
+    }
+}
+
+pub struct Blackbox<'a> {
+    process_start_time: &'a ProcessStartTime,
+    /// Do nothing if this is `None`
+    configured: Option<ConfiguredBlackbox<'a>>,
+}
+
+struct ConfiguredBlackbox<'a> {
+    repo: &'a Repo,
+    max_size: u64,
+    max_files: u32,
+    date_format: &'a str,
+}
+
+impl<'a> Blackbox<'a> {
+    pub fn new(
+        invocation: &'a CliInvocation<'a>,
+        process_start_time: &'a ProcessStartTime,
+    ) -> Result<Self, HgError> {
+        let configured = if let Ok(repo) = invocation.repo {
+            let config = invocation.config();
+            if config.get(b"extensions", b"blackbox").is_none() {
+                // The extension is not enabled
+                None
+            } else {
+                Some(ConfiguredBlackbox {
+                    repo,
+                    max_size: config
+                        .get_byte_size(b"blackbox", b"maxsize")?
+                        .unwrap_or(DEFAULT_MAX_SIZE),
+                    max_files: config
+                        .get_u32(b"blackbox", b"maxfiles")?
+                        .unwrap_or(DEFAULT_MAX_FILES),
+                    date_format: config
+                        .get_str(b"blackbox", b"date-format")?
+                        .unwrap_or(DEFAULT_DATE_FORMAT),
+                })
+            }
+        } else {
+            // Without a local repository there’s no `.hg/blackbox.log` to
+            // write to.
+            None
+        };
+        Ok(Self {
+            process_start_time,
+            configured,
+        })
+    }
+
+    pub fn log_command_start(&self) {
+        if let Some(configured) = &self.configured {
+            let message = format_bytes!(b"(rust) {}", format_cli_args());
+            configured.log(&self.process_start_time.calendar_based, &message);
+        }
+    }
+
+    pub fn log_command_end(&self, exit_code: i32) {
+        if let Some(configured) = &self.configured {
+            let now = chrono::Local::now();
+            let duration = self
+                .process_start_time
+                .monotonic_clock
+                .elapsed()
+                .as_secs_f64();
+            let message = format_bytes!(
+                b"(rust) {} exited {} after {} seconds",
+                format_cli_args(),
+                exit_code,
+                format_bytes::Utf8(format_args!("{:.03}", duration))
+            );
+            configured.log(&now, &message);
+        }
+    }
+}
+
+impl ConfiguredBlackbox<'_> {
+    fn log(&self, date_time: &DateTime, message: &[u8]) {
+        let date = format_bytes::Utf8(date_time.format(self.date_format));
+        let user = users::get_current_username().map(get_bytes_from_os_str);
+        let user = user.as_deref().unwrap_or(b"???");
+        let rev = format_bytes::Utf8(match self.repo.dirstate_parents() {
+            Ok(parents) if parents.p2 == hg::revlog::node::NULL_NODE => {
+                format!("{:x}", parents.p1)
+            }
+            Ok(parents) => format!("{:x}+{:x}", parents.p1, parents.p2),
+            Err(_dirstate_corruption_error) => {
+                // TODO: log a non-fatal warning to stderr
+                "???".to_owned()
+            }
+        });
+        let pid = std::process::id();
+        let line = format_bytes!(
+            b"{} {} @{} ({})> {}\n",
+            date,
+            user,
+            rev,
+            pid,
+            message
+        );
+        let result =
+            hg::logging::LogFile::new(self.repo.hg_vfs(), "blackbox.log")
+                .max_size(Some(self.max_size))
+                .max_files(self.max_files)
+                .write(&line);
+        match result {
+            Ok(()) => {}
+            Err(_io_error) => {
+                // TODO: log a non-fatal warning to stderr
+            }
+        }
+    }
+}
+
+fn format_cli_args() -> Vec<u8> {
+    let mut args = std::env::args_os();
+    let _ = args.next(); // Skip the first (or zeroth) arg, the name of the `rhg` executable
+    let mut args = args.map(|arg| shell_quote(&get_bytes_from_os_str(arg)));
+    let mut formatted = Vec::new();
+    if let Some(arg) = args.next() {
+        formatted.extend(arg)
+    }
+    for arg in args {
+        formatted.push(b' ');
+        formatted.extend(arg)
+    }
+    formatted
+}

rust/Cargo.lock

@@ -91,6 +91,18 b' version = "1.0.0"'
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
+name = "chrono"
+version = "0.4.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "libc 0.2.81 (registry+https://github.com/rust-lang/crates.io-index)",
+ "num-integer 0.1.44 (registry+https://github.com/rust-lang/crates.io-index)",
+ "num-traits 0.2.14 (registry+https://github.com/rust-lang/crates.io-index)",
+ "time 0.1.44 (registry+https://github.com/rust-lang/crates.io-index)",
+ "winapi 0.3.9 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
 name = "clap"
 version = "2.33.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -467,6 +479,15 b' dependencies = ['
 ]
 
 [[package]]
+name = "num-integer"
+version = "0.1.44"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "autocfg 1.0.1 (registry+https://github.com/rust-lang/crates.io-index)",
+ "num-traits 0.2.14 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
 name = "num-traits"
 version = "0.2.14"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -715,6 +736,7 b' dependencies = ['
 name = "rhg"
 version = "0.1.0"
 dependencies = [
+ "chrono 0.4.19 (registry+https://github.com/rust-lang/crates.io-index)",
  "clap 2.33.3 (registry+https://github.com/rust-lang/crates.io-index)",
  "derive_more 0.99.11 (registry+https://github.com/rust-lang/crates.io-index)",
  "env_logger 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -722,6 +744,7 b' dependencies = ['
  "hg-core 0.1.0",
  "log 0.4.11 (registry+https://github.com/rust-lang/crates.io-index)",
  "micro-timer 0.3.1 (registry+https://github.com/rust-lang/crates.io-index)",
+ "users 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
 [[package]]
@@ -856,6 +879,15 b' version = "0.2.1"'
 source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
+name = "users"
+version = "0.11.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+dependencies = [
+ "libc 0.2.81 (registry+https://github.com/rust-lang/crates.io-index)",
+ "log 0.4.11 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
+[[package]]
 name = "vcpkg"
 version = "0.2.11"
 source = "registry+https://github.com/rust-lang/crates.io-index"
@@ -949,6 +981,7 b' dependencies = ['
 "checksum cc 1.0.66 (registry+https://github.com/rust-lang/crates.io-index)" = "4c0496836a84f8d0495758516b8621a622beb77c0fed418570e50764093ced48"
 "checksum cfg-if 0.1.10 (registry+https://github.com/rust-lang/crates.io-index)" = "4785bdd1c96b2a846b2bd7cc02e86b6b3dbf14e7e53446c4f54c92a361040822"
 "checksum cfg-if 1.0.0 (registry+https://github.com/rust-lang/crates.io-index)" = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
+"checksum chrono 0.4.19 (registry+https://github.com/rust-lang/crates.io-index)" = "670ad68c9088c2a963aaa298cb369688cf3f9465ce5e2d4ca10e6e0098a1ce73"
 "checksum clap 2.33.3 (registry+https://github.com/rust-lang/crates.io-index)" = "37e58ac78573c40708d45522f0d80fa2f01cc4f9b4e2bf749807255454312002"
 "checksum const_fn 0.4.4 (registry+https://github.com/rust-lang/crates.io-index)" = "cd51eab21ab4fd6a3bf889e2d0958c0a6e3a61ad04260325e919e652a2a62826"
 "checksum cpython 0.4.1 (registry+https://github.com/rust-lang/crates.io-index)" = "bfaf3847ab963e40c4f6dd8d6be279bdf74007ae2413786a0dcbb28c52139a95"
@@ -988,6 +1021,7 b' dependencies = ['
 "checksum micro-timer 0.3.1 (registry+https://github.com/rust-lang/crates.io-index)" = "2620153e1d903d26b72b89f0e9c48d8c4756cba941c185461dddc234980c298c"
 "checksum micro-timer-macros 0.3.1 (registry+https://github.com/rust-lang/crates.io-index)" = "e28a3473e6abd6e9aab36aaeef32ad22ae0bd34e79f376643594c2b152ec1c5d"
 "checksum miniz_oxide 0.4.3 (registry+https://github.com/rust-lang/crates.io-index)" = "0f2d26ec3309788e423cfbf68ad1800f061638098d76a83681af979dc4eda19d"
+"checksum num-integer 0.1.44 (registry+https://github.com/rust-lang/crates.io-index)" = "d2cc698a63b549a70bc047073d2949cce27cd1c7b0a4a862d08a8031bc2801db"
 "checksum num-traits 0.2.14 (registry+https://github.com/rust-lang/crates.io-index)" = "9a64b1ec5cda2586e284722486d802acf1f7dbdc623e2bfc57e65ca1cd099290"
 "checksum num_cpus 1.13.0 (registry+https://github.com/rust-lang/crates.io-index)" = "05499f3756671c15885fee9034446956fff3f243d6077b91e5767df161f766b3"
 "checksum output_vt100 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "53cdc5b785b7a58c5aad8216b3dfa114df64b0b06ae6e1501cef91df2fbdf8f9"
@@ -1035,6 +1069,7 b' dependencies = ['
 "checksum typenum 1.12.0 (registry+https://github.com/rust-lang/crates.io-index)" = "373c8a200f9e67a0c95e62a4f52fbf80c23b4381c05a17845531982fa99e6b33"
 "checksum unicode-width 0.1.8 (registry+https://github.com/rust-lang/crates.io-index)" = "9337591893a19b88d8d87f2cec1e73fad5cdfd10e5a6f349f498ad6ea2ffb1e3"
 "checksum unicode-xid 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "f7fe0bb3479651439c9112f72b6c505038574c9fbb575ed1bf3b797fa39dd564"
+"checksum users 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)" = "24cc0f6d6f267b73e5a2cadf007ba8f9bc39c6a6f9666f8cf25ea809a153b032"
 "checksum vcpkg 0.2.11 (registry+https://github.com/rust-lang/crates.io-index)" = "b00bca6106a5e23f3eee943593759b7fcddb00554332e856d990c893966879fb"
 "checksum vec_map 0.8.2 (registry+https://github.com/rust-lang/crates.io-index)" = "f1bddf1187be692e79c5ffeab891132dfb0f236ed36a43c7ed39f1165ee20191"
 "checksum version_check 0.9.2 (registry+https://github.com/rust-lang/crates.io-index)" = "b5a972e5669d67ba988ce3dc826706fb0a8b01471c088cb0b6110b805cc36aed"

rust/hg-core/src/dirstate/parsers.rs

@@ -26,6 +26,14 b" type ParseResult<'a> = ("
     Vec<(&'a HgPath, &'a HgPath)>,
 );
 
+pub fn parse_dirstate_parents(
+    contents: &[u8],
+) -> Result<&DirstateParents, HgError> {
+    let (parents, _rest) = DirstateParents::from_bytes(contents)
+        .map_err(|_| HgError::corrupted("Too little data for dirstate."))?;
+    Ok(parents)
+}
+
 #[timed]
 pub fn parse_dirstate(mut contents: &[u8]) -> Result<ParseResult, HgError> {
     let mut copies = Vec::new();

rust/hg-core/src/repo.rs

@@ -214,6 +214,15 b' impl Repo {'
             base: &self.working_directory,
         }
     }
+
+    pub fn dirstate_parents(
+        &self,
+    ) -> Result<crate::dirstate::DirstateParents, HgError> {
+        let dirstate = self.hg_vfs().mmap_open("dirstate")?;
+        let parents =
+            crate::dirstate::parsers::parse_dirstate_parents(&dirstate)?;
+        Ok(parents.clone())
+    }
 }
 
 impl Vfs<'_> {

rust/hg-core/src/utils.rs

@@ -188,6 +188,35 b" pub(crate) fn strip_suffix<'a>(s: &'a st"
     }
 }
 
+#[cfg(unix)]
+pub fn shell_quote(value: &[u8]) -> Vec<u8> {
+    // TODO: Use the `matches!` macro when we require Rust 1.42+
+    if value.iter().all(|&byte| match byte {
+        b'a'..=b'z'
+        | b'A'..=b'Z'
+        | b'0'..=b'9'
+        | b'.'
+        | b'_'
+        | b'/'
+        | b'+'
+        | b'-' => true,
+        _ => false,
+    }) {
+        value.to_owned()
+    } else {
+        let mut quoted = Vec::with_capacity(value.len() + 2);
+        quoted.push(b'\'');
+        for &byte in value {
+            if byte == b'\'' {
+                quoted.push(b'\\');
+            }
+            quoted.push(byte);
+        }
+        quoted.push(b'\'');
+        quoted
+    }
+}
+
 pub fn current_dir() -> Result<std::path::PathBuf, HgError> {
     std::env::current_dir().map_err(|error| HgError::IoError {
         error,

rust/rhg/Cargo.toml

@@ -9,9 +9,11 b' edition = "2018"'
 
 [dependencies]
 hg-core = { path = "../hg-core"}
+chrono = "0.4.19"
 clap = "2.33.1"
 derive_more = "0.99"
 log = "0.4.11"
 micro-timer = "0.3.1"
 env_logger = "0.7.1"
 format-bytes = "0.2.0"
+users = "0.11.0"

rust/rhg/src/main.rs

@@ -9,6 +9,7 b' use hg::config::Config;'
 use hg::repo::{Repo, RepoError};
 use std::path::{Path, PathBuf};
 
+mod blackbox;
 mod error;
 mod exitcode;
 mod ui;
@@ -36,7 +37,10 b" fn add_global_args<'a, 'b>(app: App<'a, "
     )
 }
 
-fn main_with_result(ui: &ui::Ui) -> Result<(), CommandError> {
+fn main_with_result(
+    ui: &ui::Ui,
+    process_start_time: &blackbox::ProcessStartTime,
+) -> Result<(), CommandError> {
     env_logger::init();
     let app = App::new("rhg")
         .setting(AppSettings::AllowInvalidUtf8)
@@ -83,35 +87,47 b' fn main_with_result(ui: &ui::Ui) -> Resu'
         Err(error) => return Err(error.into()),
     };
 
-    run(&CliInvocation {
+    let invocation = CliInvocation {
         ui,
         subcommand_args,
         non_repo_config,
         repo: repo.as_ref(),
-    })
+    };
+    let blackbox = blackbox::Blackbox::new(&invocation, process_start_time)?;
+    blackbox.log_command_start();
+    let result = run(&invocation);
+    blackbox.log_command_end(exit_code(&result));
+    result
 }
 
 fn main() {
+    // Run this first, before we find out if the blackbox extension is even
+    // enabled, in order to include everything in-between in the duration
+    // measurements. Reading config files can be slow if they’re on NFS.
+    let process_start_time = blackbox::ProcessStartTime::now();
+
     let ui = ui::Ui::new();
 
-    let exit_code = match main_with_result(&ui) {
+    let result = main_with_result(&ui, &process_start_time);
+    if let Err(CommandError::Abort { message }) = &result {
+        if !message.is_empty() {
+            // Ignore errors when writing to stderr, we’re already exiting
+            // with failure code so there’s not much more we can do.
+            let _ = ui.write_stderr(&format_bytes!(b"abort: {}\n", message));
+        }
+    }
+    std::process::exit(exit_code(&result))
+}
+
+fn exit_code(result: &Result<(), CommandError>) -> i32 {
+    match result {
         Ok(()) => exitcode::OK,
+        Err(CommandError::Abort { .. }) => exitcode::ABORT,
 
         // Exit with a specific code and no error message to let a potential
         // wrapper script fallback to Python-based Mercurial.
         Err(CommandError::Unimplemented) => exitcode::UNIMPLEMENTED,
-
-        Err(CommandError::Abort { message }) => {
-            if !message.is_empty() {
-                // Ignore errors when writing to stderr, we’re already exiting
-                // with failure code so there’s not much more we can do.
-                let _ =
-                    ui.write_stderr(&format_bytes!(b"abort: {}\n", message));
-            }
-            exitcode::ABORT
-        }
-    };
-    std::process::exit(exit_code)
+    }
 }
 
 macro_rules! subcommands {

tests/test-rhg.t

@@ -261,3 +261,15 b' And check that basic rhg commands work w'
   $ rhg cat -r 0 a
   a
 
+The blackbox extension is supported
+
+  $ echo "[extensions]" >> $HGRCPATH
+  $ echo "blackbox =" >> $HGRCPATH
+  $ echo "[blackbox]" >> $HGRCPATH
+  $ echo "maxsize = 1" >> $HGRCPATH
+  $ rhg files > /dev/null
+  $ cat .hg/blackbox.log
+  ????/??/?? ??:??:??.??? * @d3873e73d99ef67873dac33fbcc66268d5d2b6f4 (*)> (rust) files exited 0 after 0.??? seconds (glob)
+  $ cat .hg/blackbox.log.1
+  ????/??/?? ??:??:??.??? * @d3873e73d99ef67873dac33fbcc66268d5d2b6f4 (*)> (rust) files (glob)
+