Mercurial > hg
changeset 46601:755c31a1caf9
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
| author | Simon Sapin <simon.sapin@octobus.net> |
|---|---|
| date | Tue, 16 Feb 2021 13:08:37 +0100 |
| parents | 36f3a64846c8 |
| children | a687a7f27951 |
| files | rust/Cargo.lock rust/hg-core/src/dirstate/parsers.rs rust/hg-core/src/repo.rs rust/hg-core/src/utils.rs rust/rhg/Cargo.toml rust/rhg/src/blackbox.rs rust/rhg/src/main.rs tests/test-rhg.t |
| diffstat | 8 files changed, 288 insertions(+), 16 deletions(-) [+] |
line wrap: on
line diff
--- a/rust/Cargo.lock Wed Feb 17 13:00:25 2021 +0100 +++ b/rust/Cargo.lock Tue Feb 16 13:08:37 2021 +0100 @@ -91,6 +91,18 @@ 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 @@ ] [[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 @@ 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 @@ "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 @@ 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 @@ "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 @@ "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 @@ "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"
--- a/rust/hg-core/src/dirstate/parsers.rs Wed Feb 17 13:00:25 2021 +0100 +++ b/rust/hg-core/src/dirstate/parsers.rs Tue Feb 16 13:08:37 2021 +0100 @@ -26,6 +26,14 @@ 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();
--- a/rust/hg-core/src/repo.rs Wed Feb 17 13:00:25 2021 +0100 +++ b/rust/hg-core/src/repo.rs Tue Feb 16 13:08:37 2021 +0100 @@ -214,6 +214,15 @@ 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<'_> {
--- a/rust/hg-core/src/utils.rs Wed Feb 17 13:00:25 2021 +0100 +++ b/rust/hg-core/src/utils.rs Tue Feb 16 13:08:37 2021 +0100 @@ -188,6 +188,35 @@ } } +#[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,
--- a/rust/rhg/Cargo.toml Wed Feb 17 13:00:25 2021 +0100 +++ b/rust/rhg/Cargo.toml Tue Feb 16 13:08:37 2021 +0100 @@ -9,9 +9,11 @@ [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"
--- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/rust/rhg/src/blackbox.rs Tue Feb 16 13:08:37 2021 +0100 @@ -0,0 +1,161 @@ +//! 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 +}
--- a/rust/rhg/src/main.rs Wed Feb 17 13:00:25 2021 +0100 +++ b/rust/rhg/src/main.rs Tue Feb 16 13:08:37 2021 +0100 @@ -9,6 +9,7 @@ use hg::repo::{Repo, RepoError}; use std::path::{Path, PathBuf}; +mod blackbox; mod error; mod exitcode; mod ui; @@ -36,7 +37,10 @@ ) } -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 @@ 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 {
--- a/tests/test-rhg.t Wed Feb 17 13:00:25 2021 +0100 +++ b/tests/test-rhg.t Tue Feb 16 13:08:37 2021 +0100 @@ -261,3 +261,15 @@ $ 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) +