diff --git a/Cargo.lock b/Cargo.lock index 08be41e8ce0..8012c22a833 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1297,6 +1297,7 @@ dependencies = [ "prost", "rand", "regex", + "reopen", "rocksdb", "rust_decimal", "rust_decimal_macros", @@ -3306,6 +3307,15 @@ dependencies = [ "bytecheck", ] +[[package]] +name = "reopen" +version = "1.0.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ff42cec3acf85845f5b18b3cbb7fec619ccbd4a349f6ecbe1c62ab46d4d98293" +dependencies = [ + "autocfg", +] + [[package]] name = "ring" version = "0.16.20" diff --git a/Dockerfile b/Dockerfile index a05c435a38d..bb1de828171 100644 --- a/Dockerfile +++ b/Dockerfile @@ -203,23 +203,22 @@ FROM alpine:${ALPINE_VERSION} AS drive-abci LABEL maintainer="Dash Developers " LABEL description="Drive ABCI Rust" -WORKDIR /var/lib/dash - RUN apk add --no-cache libgcc libstdc++ +ENV DB_PATH=/var/lib/dash/rs-drive-abci/db + +RUN mkdir -p /var/log/dash \ + /var/lib/dash/rs-drive-abci/db + COPY --from=build-drive-abci /artifacts/drive-abci /usr/bin/drive-abci COPY --from=build-drive-abci /platform/packages/rs-drive-abci/.env.example /var/lib/dash/rs-drive-abci/.env -# Double-check that we don't have missing deps -RUN ldd /usr/bin/drive-abci - # Create a volume -VOLUME /var/lib/dash +VOLUME /var/lib/dash/rs-drive-abci/db VOLUME /var/log/dash -RUN mkdir -p /var/log/dash - -ENV DB_PATH=/var/lib/dash/rs-drive-abci/db +# Double-check that we don't have missing deps +RUN ldd /usr/bin/drive-abci # # Create new non-root user diff --git a/docs/DRIVE-ABCI.md b/docs/DRIVE-ABCI.md index 82681b9d9e5..15c9ca6c91a 100644 --- a/docs/DRIVE-ABCI.md +++ b/docs/DRIVE-ABCI.md @@ -10,7 +10,7 @@ Configuration is implemented using environment variables. Environment variables ### Logging -The logging configuration allows you to configure multiple logging destinations. Each destination is defined using a series of environment variables prefixed with ABCI_LOG_*key*, where *key* is an arbitrary name for the destination. +The logging configuration allows you to configure multiple logging destinations. Each destination is defined using a series of environment variables prefixed with ABCI_LOG_*key*_*option*, where *key* is an arbitrary name for the destination. The log destination configuration consists of the following parameters: @@ -22,22 +22,31 @@ Specifies the destination of the logs. It can have one of the following values: * **stderr**: Logs will be sent to the standard error * An absolute path to an existing directory where logs will be stored, for example `/var/log/dash/` -#### VERBOSITY (optional) +#### LEVEL (optional) -Specifies the verbosity level of the logs. It is an integer value ranging from 0 to 5. Defaults to 0. Higher values indicate more detailed and verbose logs. For more information on verbosity levels, refer to the `-v` option in the `drive-abci --help` command. +Specifies the logs verbosity level preset: + +* **silent**: No logs. +* **custom**: Uses RUST_LOG env or info level if not set. +* **error**: Only errors. +* **warn**: Warnings and errors. Errors for 3rd party dependencies. +* **info**: Info level and lower. Warnings for 3rd party dependencies. Default. +* **debug**: Debug level and lower. Info level for 3rd party dependencies. +* **trace**: Trace level and lower. Debug level for 3rd party dependencies. +* **paranoid**: Trace level for everything. #### COLOR (optional) -Specifies whether or not to use colorful output for the logs. It is an optional boolean parameter. If not provided, the output colorization will be autodetected. +Specifies whether to use colorful output for the logs. It is an optional boolean parameter. If not provided, the output colorization will be autodetected. #### FORMAT (optional) Specifies the output format to use for the logs. It can have one of the following values: -* **Full**: Logs will be formatted with full details. -* **Compact**: Logs will be formatted in a compact manner. -* **Pretty**: Logs will be formatted in a human-readable and visually appealing manner. -* **Json**: Logs will be formatted in JSON format. +* **full**: Logs will be formatted with full details. +* **compact**: Logs will be formatted in a compact manner. +* **pretty**: Logs will be formatted in a human-readable and visually appealing manner. +* **json**: Logs will be formatted in JSON format. For more detailed description for different formats, refer to the [tracing-subscriber](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/format/index.html#formatters) documentation. @@ -54,7 +63,7 @@ To configure multiple logging destinations, each destination should have its own For example, to configure a logging destination with the key "example", you would set the following environment variables: * ABCI_LOG_EXAMPLE_DESTINATION: Specifies the destination of logs for the "example" destination. -* ABCI_LOG_EXAMPLE_VERBOSITY: Specifies the verbosity level for the "example" destination. +* ABCI_LOG_EXAMPLE_LEVEL: Specifies the verbosity level for the "example" destination. * ABCI_LOG_EXAMPLE_COLOR: Specifies whether to use colorful output for the "example" destination (optional). * ABCI_LOG_EXAMPLE_FORMAT: Specifies the output format for the "example" destination (optional). * ABCI_LOG_EXAMPLE_MAX_FILES: Specifies the maximum number of daily log files to store for the "example" destination (optional). @@ -67,9 +76,9 @@ Here's an example configuration for a logging destination named "EXAMPLE": ```bash export ABCI_LOG_EXAMPLE_DESTINATION="/var/log/example" -export ABCI_LOG_EXAMPLE_VERBOSITY=3 +export ABCI_LOG_EXAMPLE_LEVEL=debug export ABCI_LOG_EXAMPLE_COLOR=false -export ABCI_LOG_EXAMPLE_FORMAT="Pretty" +export ABCI_LOG_EXAMPLE_FORMAT="pretty" export ABCI_LOG_EXAMPLE_MAX_FILES=10 ``` diff --git a/packages/dashmate/configs/getConfigFileMigrationsFactory.js b/packages/dashmate/configs/getConfigFileMigrationsFactory.js index 0a52cdb39fd..265ec57a7ea 100644 --- a/packages/dashmate/configs/getConfigFileMigrationsFactory.js +++ b/packages/dashmate/configs/getConfigFileMigrationsFactory.js @@ -148,6 +148,14 @@ function getConfigFileMigrationsFactory(homeDir, defaultConfigs) { options.platform.drive.tenderdash.docker.image = base.get('platform.drive.tenderdash.docker.image'); } + if (options.platform.drive.abci.log.jsonFile.level === 'fatal') { + options.platform.drive.abci.log.jsonFile.level = 'error'; + } + + if (options.platform.drive.abci.log.prettyFile.level === 'fatal') { + options.platform.drive.abci.log.prettyFile.level = 'error'; + } + if (options.network === NETWORK_TESTNET) { options.platform.drive.tenderdash.genesis.chain_id = testnet.get('platform.drive.tenderdash.genesis.chain_id'); options.platform.drive.tenderdash diff --git a/packages/dashmate/docker-compose.yml b/packages/dashmate/docker-compose.yml index 7559377b9e5..9d278c5cd02 100644 --- a/packages/dashmate/docker-compose.yml +++ b/packages/dashmate/docker-compose.yml @@ -45,8 +45,9 @@ services: org.dashmate.service.title: "Drive ABCI" restart: unless-stopped volumes: - - drive_abci_data:/var/lib/dash/rs-drive-abci - - drive_abci_logs:/var/log/dash + - drive_abci_data:/var/lib/dash/rs-drive-abci/db + - ${PLATFORM_DRIVE_ABCI_LOG_PRETTY_DIRECTORY_PATH:?err}:/var/log/dash/drive/pretty + - ${PLATFORM_DRIVE_ABCI_LOG_JSON_DIRECTORY_PATH:?err}:/var/log/dash/drive/json environment: - BLOCK_SPACING_MS=3000 # TODO: sync with tenderdash - CHAIN_ID=devnet # TODO: sync with tenderdash chain id @@ -68,8 +69,18 @@ services: - WITHDRAWALS_SECOND_PUBLIC_KEY=${PLATFORM_WITHDRAWALS_SECOND_PUBLIC_KEY} - QUORUM_SIZE=5 # TODO: sync with Tenderdash - QUORUM_TYPE=${PLATFORM_DRIVE_ABCI_VALIDATOR_SET_LLMQ_TYPE:?err} - - NETWORK=${NETWORK} - - TENDERDASH_P2P_PORT=${PLATFORM_DRIVE_TENDERDASH_P2P_PORT} + - NETWORK=${NETWORK:?err} + - TENDERDASH_P2P_PORT=${PLATFORM_DRIVE_TENDERDASH_P2P_PORT:?err} + - ABCI_LOG_STDOUT_DESTINATION=stdout + - ABCI_LOG_STDOUT_LEVEL=${PLATFORM_DRIVE_ABCI_LOG_STDOUT_LEVEL:?err} + - ABCI_LOG_STDOUT_FORMAT=pretty + - ABCI_LOG_STDOUT_COLOR=true + - ABCI_LOG_PRETTY_DESTINATION=/var/log/dash/drive/pretty/${PLATFORM_DRIVE_ABCI_LOG_PRETTY_FILE_NAME:?err} + - ABCI_LOG_PRETTY_LEVEL=${PLATFORM_DRIVE_ABCI_LOG_PRETTY_FILE_LEVEL:?err} + - ABCI_LOG_PRETTY_FORMAT=pretty + - ABCI_LOG_JSON_DESTINATION=/var/log/dash/drive/json/${PLATFORM_DRIVE_ABCI_LOG_JSON_FILE_NAME:?err} + - ABCI_LOG_JSON_LEVEL=${PLATFORM_DRIVE_ABCI_LOG_JSON_FILE_LEVEL:?err} + - ABCI_LOG_JSON_FORMAT=json stop_grace_period: 30s profiles: - platform diff --git a/packages/dashmate/src/commands/stop.js b/packages/dashmate/src/commands/stop.js index 077ed670f1e..84259285446 100644 --- a/packages/dashmate/src/commands/stop.js +++ b/packages/dashmate/src/commands/stop.js @@ -65,7 +65,6 @@ StopCommand.flags = { description: 'stop only platform', default: false, }), - }; module.exports = StopCommand; diff --git a/packages/dashmate/src/config/configJsonSchema.js b/packages/dashmate/src/config/configJsonSchema.js index f8368521eaa..80c4cbf7ac7 100644 --- a/packages/dashmate/src/config/configJsonSchema.js +++ b/packages/dashmate/src/config/configJsonSchema.js @@ -77,7 +77,7 @@ module.exports = { properties: { level: { type: 'string', - enum: ['fatal', 'error', 'warn', 'info', 'debug', 'trace', 'silent'], + enum: ['error', 'warn', 'info', 'debug', 'trace', 'silent'], }, path: { type: 'string', diff --git a/packages/dashmate/src/listr/tasks/setup/setupLocalPresetTaskFactory.js b/packages/dashmate/src/listr/tasks/setup/setupLocalPresetTaskFactory.js index 56940c3eb4c..75ed95bd5d1 100644 --- a/packages/dashmate/src/listr/tasks/setup/setupLocalPresetTaskFactory.js +++ b/packages/dashmate/src/listr/tasks/setup/setupLocalPresetTaskFactory.js @@ -229,6 +229,12 @@ function setupLocalPresetTaskFactory( config.set('platform.drive.tenderdash.mode', 'validator'); // Setup logs + const drivePrettyFilePath = homeDir.joinPath('logs', config.getName(), 'drive-pretty.log'); + config.set('platform.drive.abci.log.prettyFile.path', drivePrettyFilePath); + + const driveJsonFilePath = homeDir.joinPath('logs', config.getName(), 'drive-json.log'); + config.set('platform.drive.abci.log.jsonFile.path', driveJsonFilePath); + if (ctx.debugLogs) { config.set('platform.drive.abci.log.stdout.level', 'trace'); config.set('platform.drive.abci.log.prettyFile.level', 'trace'); @@ -236,16 +242,6 @@ function setupLocalPresetTaskFactory( config.set('platform.drive.tenderdash.log.level', 'debug'); } - if (!config.get('platform.drive.abci.log.prettyFile.path')) { - const drivePrettyLogFile = homeDir.joinPath('logs', config.getName(), 'drive_pretty.log'); - config.set('platform.drive.abci.log.prettyFile.path', drivePrettyLogFile); - } - - if (!config.get('platform.drive.abci.log.jsonFile.path')) { - const driveJsonLogFile = homeDir.joinPath('logs', config.getName(), 'drive_json.log'); - config.set('platform.drive.abci.log.jsonFile.path', driveJsonLogFile); - } - config.set('platform.dpns.masterPublicKey', dpnsDerivedMasterPrivateKey.privateKey.toPublicKey().toString()); config.set('platform.dpns.secondPublicKey', dpnsDerivedSecondPrivateKey.privateKey.toPublicKey().toString()); diff --git a/packages/dashmate/test/e2e/localNetwork.js b/packages/dashmate/test/e2e/localNetwork.js index 046cfd9169c..6ba55205963 100644 --- a/packages/dashmate/test/e2e/localNetwork.js +++ b/packages/dashmate/test/e2e/localNetwork.js @@ -32,6 +32,7 @@ describe('Local Network', function main() { // Update local config template that will be used to setup nodes const localConfig = configFile.getConfig(groupName); localConfig.set('dashmate.helper.docker.build.enabled', true); + localConfig.set('platform.drive.abci.docker.build.enabled', true); localConfig.set('docker.network.subnet', '172.30.0.0/24'); localConfig.set('dashmate.helper.api.port', 40000); localConfig.set('core.p2p.port', 40001); diff --git a/packages/dashmate/test/e2e/testnetFullnode.spec.js b/packages/dashmate/test/e2e/testnetFullnode.spec.js index 21ef84c19ff..30091f6f2e5 100644 --- a/packages/dashmate/test/e2e/testnetFullnode.spec.js +++ b/packages/dashmate/test/e2e/testnetFullnode.spec.js @@ -96,6 +96,7 @@ describe('Testnet Fullnode', function main() { config = configFile.getConfig(preset); config.set('dashmate.helper.docker.build.enabled', true); + config.set('platform.drive.abci.docker.build.enabled', true); config.set('docker.network.subnet', '172.27.24.0/24'); config.set('dashmate.helper.api.port', 40000); config.set('core.p2p.port', 40001); diff --git a/packages/dashmate/test/e2e/testnetHPFullnode.spec.js b/packages/dashmate/test/e2e/testnetHPFullnode.spec.js index def330a2ecc..15ec93c3904 100644 --- a/packages/dashmate/test/e2e/testnetHPFullnode.spec.js +++ b/packages/dashmate/test/e2e/testnetHPFullnode.spec.js @@ -96,6 +96,7 @@ describe('Testnet HP Fullnode', function main() { config = configFile.getConfig(preset); config.set('dashmate.helper.docker.build.enabled', true); + config.set('platform.drive.abci.docker.build.enabled', true); config.set('docker.network.subnet', '172.27.24.0/24'); config.set('dashmate.helper.api.port', 40000); config.set('core.p2p.port', 40001); diff --git a/packages/rs-drive-abci/.env.example b/packages/rs-drive-abci/.env.example index 68ac2e5bf0a..9350e56b39b 100644 --- a/packages/rs-drive-abci/.env.example +++ b/packages/rs-drive-abci/.env.example @@ -3,20 +3,10 @@ ABCI_BIND_ADDRESS="tcp://0.0.0.0:26658" ABCI_PROMETHEUS_BIND_ADDRESS="http://0.0.0.0:29090" # stderr logging for humans -ABCI_LOG_STDERR_DESTINATION=stderr -ABCI_LOG_STDERR_VERBOSITY=1 -ABCI_LOG_STDERR_FORMAT=Pretty -ABCI_LOG_STDERR_COLOR=true - -# stdout logging for machines (elasticsearch) ABCI_LOG_STDOUT_DESTINATION=stdout -ABCI_LOG_STDOUT_VERBOSITY=4 -ABCI_LOG_STDOUT_FORMAT=Json - -# file logging for humans, but very verbose; no log rotation -ABCI_LOG_FILE_DESTINATION=/var/log/dash -ABCI_LOG_FILE_VERBOSITY=5 -ABCI_LOG_FILE_MAX_FILES=0 +ABCI_LOG_STDOUT_LEVEL=info +ABCI_LOG_STDOUT_FORMAT=pretty +ABCI_LOG_STDOUT_COLOR=true DB_PATH=/tmp/db diff --git a/packages/rs-drive-abci/Cargo.toml b/packages/rs-drive-abci/Cargo.toml index e8346e19648..8d497f0442a 100644 --- a/packages/rs-drive-abci/Cargo.toml +++ b/packages/rs-drive-abci/Cargo.toml @@ -38,7 +38,7 @@ prost = { version = "0.11.6", default-features = false } tracing = { version = "0.1.37", default-features = false, features = [] } clap = { version = "4.1.8", optional = true, features = ["derive"] } envy = { version = "0.4.2" } -dotenvy = { version = "0.15.6", optional = true } +dotenvy = { version = "0.15.7", optional = true } dapi-grpc = { path = "../dapi-grpc" } platform-serialization = { path = "../rs-platform-serialization" } platform-serialization-derive = { path = "../rs-platform-serialization-derive" } @@ -58,6 +58,7 @@ anyhow = { version = "1.0.70" } lazy_static = "1.4.0" itertools = { version = "0.10.5" } file-rotate = { version = "0.7.3" } +reopen = { version = "1.0.3" } delegate = { version = "0.9.0" } regex = { version = "1.8.1" } metrics = { version = "0.21" } diff --git a/packages/rs-drive-abci/src/abci/handlers.rs b/packages/rs-drive-abci/src/abci/handlers.rs index b8f75b197b5..038d2fb63c8 100644 --- a/packages/rs-drive-abci/src/abci/handlers.rs +++ b/packages/rs-drive-abci/src/abci/handlers.rs @@ -169,11 +169,11 @@ where if let Some(core_chain_lock_update) = core_chain_lock_update.as_ref() { // We can't add this, as it slows down CI way too much // todo: find a way to re-enable this without destroying CI - // tracing::info!( - // "chain lock update to height {} at block {}", - // core_chain_lock_update.core_block_height, - // request.height - // ); + tracing::debug!( + "propose chain lock update to height {} at block {}", + core_chain_lock_update.core_block_height, + request.height + ); block_proposal.core_chain_locked_height = core_chain_lock_update.core_block_height; } diff --git a/packages/rs-drive-abci/src/config.rs b/packages/rs-drive-abci/src/config.rs index 939e9ea212f..6034bc0dd92 100644 --- a/packages/rs-drive-abci/src/config.rs +++ b/packages/rs-drive-abci/src/config.rs @@ -280,9 +280,16 @@ mod tests { fn test_config_from_env() { // ABCI log configs are parsed manually, so they deserve separate handling // Notat that STDOUT is also defined in .env.example, but env var should overwrite it. - let log_ids = &["STDOUT", "UPPERCASE", "lowercase", "miXedC4s3", "123"]; - for id in log_ids { - env::set_var(format!("ABCI_LOG_{}_DESTINATION", id), "bytes"); + let vectors = &[ + ("STDOUT", "pretty"), + ("UPPERCASE", "json"), + ("lowercase", "pretty"), + ("miXedC4s3", "full"), + ("123", "compact"), + ]; + for vector in vectors { + env::set_var(format!("ABCI_LOG_{}_DESTINATION", vector.0), "bytes"); + env::set_var(format!("ABCI_LOG_{}_FORMAT", vector.0), vector.1); } let envfile = std::path::PathBuf::from(env!("CARGO_MANIFEST_DIR")).join(".env.example"); @@ -293,8 +300,8 @@ mod tests { let config = super::PlatformConfig::from_env().unwrap(); assert!(config.verify_sum_trees); assert_ne!(config.quorum_type(), QuorumType::UNKNOWN); - for id in log_ids { - assert_eq!(config.abci.log[*id].destination.as_str(), "bytes"); + for id in vectors { + assert_eq!(config.abci.log[id.0].destination.as_str(), "bytes"); } } } diff --git a/packages/rs-drive-abci/src/logging.rs b/packages/rs-drive-abci/src/logging.rs index 6e7ffde0f60..a4db0aab348 100644 --- a/packages/rs-drive-abci/src/logging.rs +++ b/packages/rs-drive-abci/src/logging.rs @@ -6,17 +6,20 @@ use file_rotate::TimeFrequency; use itertools::Itertools; use lazy_static::__Deref; use regex::Regex; +use reopen::Reopen; use serde::Deserialize; use serde::Serialize; use std::collections::HashMap; use std::fmt::Debug; use std::fs::File; use std::fs::OpenOptions; +use std::io::Write; use std::os::unix::prelude::OpenOptionsExt; use std::path::Path; use std::path::PathBuf; use std::sync::Arc; use std::sync::Mutex; +use std::{fs, path}; use tracing::metadata::LevelFilter; use tracing_subscriber::fmt; use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt; @@ -29,6 +32,11 @@ use tracing_subscriber::Registry; use crate::config::FromEnv; +const LOG_DESTINATION_STDOUT: &str = "stdout"; +const LOG_DESTINATION_STDERR: &str = "stderr"; +#[cfg(test)] +const LOG_DESTINATION_BYTES: &str = "bytes"; + /// Logging configuration. #[derive(Serialize, Deserialize, Debug, Clone)] pub struct LogConfig { @@ -37,29 +45,29 @@ pub struct LogConfig { /// One of: /// * "stdout", /// * "stderr", - /// * absolute path to existing directory where log files will be stored + /// * absolute path to log file /// /// For testing, also "bytes" is available. pub destination: String, - /// Verbosity level, 0 to 5; see `-v` option in `drive-abci --help` for more details. + /// Log level: silent, error, info, warn, debug, trace #[serde(default)] - pub verbosity: u8, + pub level: LogLevelPreset, /// Whether or not to use colorful output; defaults to autodetect #[serde(default)] pub color: Option, /// Output format to use. /// /// One of: - /// * Full - /// * Compact - /// * Pretty - /// * Json + /// * full + /// * compact + /// * pretty + /// * json /// /// See https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/format/index.html#formatters for more /// detailed description. #[serde(default)] pub format: LogFormat, - /// Max number of daily files to store; only used when storing logs in file; defaults to 0 - rotation disabled + /// Max number of daily files to store, excluding active one; only used when storing logs in file; defaults to 0 - rotation disabled #[serde(default)] pub max_files: usize, } @@ -67,11 +75,76 @@ pub struct LogConfig { impl Default for LogConfig { fn default() -> Self { Self { - destination: String::from("stderr"), - verbosity: 0, - color: None, + destination: LOG_DESTINATION_STDOUT.to_string(), + level: Default::default(), + color: Default::default(), format: Default::default(), - max_files: 0, + max_files: Default::default(), + } + } +} + +/// Log level presets +#[derive(Serialize, Deserialize, Debug, Clone, Default)] +#[serde(rename_all = "camelCase")] +pub enum LogLevelPreset { + /// No logs + Silent, + /// Uses RUST_LOG env or info level if not set + Custom, + /// Only errors + Error, + /// Warnings and errors. Errors for 3rd party dependencies + Warn, + /// Info level and lower. Warnings for 3rd party dependencies + #[default] + Info, + /// Debug level and lower. Info level for 3rd party dependencies + Debug, + /// Trace level and lower. Debug level for 3rd party dependencies + Trace, + /// Trace level for everything + Paranoid, +} + +/// Creates log level preset from verbosity level +impl TryFrom for LogLevelPreset { + type Error = Error; + + fn try_from(value: u8) -> Result>::Error> { + let level = match value { + 0 => LogLevelPreset::Custom, + 1 => LogLevelPreset::Debug, + 2 => LogLevelPreset::Trace, + 3 => LogLevelPreset::Paranoid, + verbosity => return Err(Error::InvalidVerbosityLevel(verbosity)), + }; + + Ok(level) + } +} + +impl From<&LogLevelPreset> for EnvFilter { + fn from(value: &LogLevelPreset) -> Self { + match value { + LogLevelPreset::Silent => EnvFilter::default(), + LogLevelPreset::Custom => EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .from_env_lossy(), + LogLevelPreset::Error => EnvFilter::new("error"), + LogLevelPreset::Warn => { + EnvFilter::new("error,tenderdash_abci=warn,drive_abci=warn,drive=warn,dpp=warn") + } + LogLevelPreset::Info => { + EnvFilter::new("error,tenderdash_abci=info,drive_abci=info,drive=info,dpp=info") + } + LogLevelPreset::Debug => { + EnvFilter::new("info,tenderdash_abci=debug,drive_abci=debug,drive=debug,dpp=debug") + } + LogLevelPreset::Trace => { + EnvFilter::new("debug,tenderdash_abci=trace,drive_abci=trace,drive=trace,dpp=trace") + } + LogLevelPreset::Paranoid => EnvFilter::new("trace"), } } } @@ -80,6 +153,7 @@ impl Default for LogConfig { /// /// See https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/index.html#formatters #[derive(Debug, Serialize, Deserialize, Default, Clone, Copy)] +#[serde(rename_all = "camelCase")] pub enum LogFormat { /// Default, human-readable, single-line logs #[default] @@ -106,11 +180,11 @@ pub enum LogFormat { /// ```bash /// # First logger, logging to stderr on verbosity level 5 /// ABCI_LOG_STDERR_DESTINATION=stderr -/// ABCI_LOG_STDERR_VERBOSITY=6 +/// ABCI_LOG_STDERR_LEVEL=trace /// /// # Second logger, logging to stdout on verbosity level 1 /// ABCI_LOG_STDOUT_DESTINATION=stdout -/// ABCI_LOG_STDOUT_VERBOSITY=1 +/// ABCI_LOG_STDOUT_LEVEL=info /// ``` /// /// @@ -167,6 +241,10 @@ pub enum Error { /// Duplicate config #[error("duplicate log configuration name {0}")] DuplicateConfigName(String), + + /// Undefined verbosity level + #[error("undefined log verbosity level {0}")] + InvalidVerbosityLevel(u8), } /// Name of logging configuration @@ -369,13 +447,22 @@ impl Loggers { let cloned = logger.destination.clone(); let guard = cloned.lock().expect("logging lock poisoned"); - if let LogDestination::RotationWriter(writer) = guard.deref() { - let mut inner = writer.0.lock().expect("logging lock poisoned"); - // let inner = guard.get_mut(); - if let Err(e) = inner.rotate() { - result = Err(Error::FileRotate(e)); - }; - }; + match guard.deref() { + LogDestination::RotationWriter(ref writer) => { + let mut inner = writer.0.lock().expect("logging lock poisoned"); + if let Err(e) = inner.rotate() { + result = Err(Error::FileRotate(e)); + }; + } + LogDestination::File(ref f) => { + let mut inner = f.0.lock().expect("logging lock poisoned"); + + result = inner.flush().map_err(Error::FileRotate).map(|_| { + inner.handle().reopen(); + }) + } + _ => {} + } } result } @@ -461,7 +548,7 @@ enum LogDestination { /// Standard out StdOut, /// Standard file - File(Writer), + File(Writer>), /// File that is logrotated RotationWriter(Writer>), #[cfg(test)] @@ -504,7 +591,7 @@ impl Debug for LogDestination { } /// Whenever we want to write to log destination, we delegate to the Writer implementation -impl std::io::Write for LogDestination { +impl Write for LogDestination { delegate::delegate! { to self.to_write() { #[inline] @@ -525,7 +612,7 @@ impl std::io::Write for LogDestination { } } -impl TryFrom<&LogConfig> for file_rotate::FileRotate { +impl TryFrom<&LogConfig> for FileRotate { type Error = Error; /// Configure new FileRotate based on log configuration. /// @@ -536,29 +623,37 @@ impl TryFrom<&LogConfig> for file_rotate::FileRotate { let compression = file_rotate::compression::Compression::OnRotate(2); // Only owner can see logs let mode = Some(0o600); - let path = log_file_path(PathBuf::from(&config.destination))?; - let f = file_rotate::FileRotate::new(path, suffix_scheme, content_limit, compression, mode); + let path = PathBuf::from(&config.destination); + + validate_log_path(&path)?; + + let f = FileRotate::new(path, suffix_scheme, content_limit, compression, mode); Ok(f) } } -impl TryFrom<&LogConfig> for File { +impl TryFrom<&LogConfig> for Reopen { type Error = Error; /// Configure new File based on log configuration. fn try_from(config: &LogConfig) -> Result { // Only owner can see logs let mode = 0o600; - let path = log_file_path(PathBuf::from(&config.destination))?; - - let f = OpenOptions::new() - .create(true) - .append(true) - .mode(mode) - .open(&path) - .map_err(|e| Error::FileCreate(path, e))?; + let path = PathBuf::from(&config.destination); + + validate_log_path(&path)?; + + let opened_path = path.clone(); + let open_fn = move || { + OpenOptions::new() + .create(true) + .write(true) + .append(true) + .mode(mode) + .open(&opened_path) + }; - Ok(f) + Reopen::new(Box::new(open_fn)).map_err(|e| Error::FileCreate(path, e)) } } @@ -568,8 +663,8 @@ struct Logger { /// Destination of logs; either absolute path to dir where log files will be stored, `stdout` or `stderr` destination: Arc>, - /// Log verbosity level, number; see [super::Cli::verbose]. - verbosity: u8, + /// Log verbosity level preset + level: LogLevelPreset, /// Whether to use colored output color: Option, @@ -582,10 +677,10 @@ impl TryFrom<&LogConfig> for Logger { type Error = Error; fn try_from(config: &LogConfig) -> Result { let destination = match config.destination.to_lowercase().as_str() { - "stdout" => LogDestination::StdOut, - "stderr" => LogDestination::StdErr, + LOG_DESTINATION_STDOUT => LogDestination::StdOut, + LOG_DESTINATION_STDERR => LogDestination::StdErr, #[cfg(test)] - "bytes" => LogDestination::Bytes(Vec::::new().into()), + LOG_DESTINATION_BYTES => LogDestination::Bytes(Vec::::new().into()), dest => { // we refer directly to config.destination, as dest was converted to lowercase let path = PathBuf::from(&config.destination); @@ -596,20 +691,17 @@ impl TryFrom<&LogConfig> for Logger { let file: FileRotate = FileRotate::try_from(config)?; LogDestination::RotationWriter(file.into()) } else { - let file: File = File::try_from(config)?; + let file: Reopen = config.try_into()?; LogDestination::File(file.into()) } } }; - let verbosity = config.verbosity; - let color = config.color; - let format = config.format; Ok(Self { destination: Arc::new(Mutex::new(destination)), - verbosity, - color, - format, + level: config.level.clone(), + color: config.color, + format: config.format, }) } } @@ -617,8 +709,8 @@ impl TryFrom<&LogConfig> for Logger { impl Default for Logger { fn default() -> Self { Self { - destination: Arc::new(Mutex::new(LogDestination::StdErr)), - verbosity: 0, + destination: Arc::new(Mutex::new(LogDestination::StdOut)), + level: LogLevelPreset::Info, color: None, format: LogFormat::Full, } @@ -640,7 +732,7 @@ impl Logger { let cloned = self.destination.clone(); let make_writer = { move || Writer(Arc::clone(&cloned)) }; - let filter = self.env_filter(); + let filter = EnvFilter::from(&self.level); let formatter = fmt::layer::() .with_writer(make_writer) @@ -653,31 +745,17 @@ impl Logger { LogFormat::Json => formatter.json().with_filter(filter).boxed(), } } - - fn env_filter(&self) -> EnvFilter { - match self.verbosity { - 0 => EnvFilter::builder() - .with_default_directive(LevelFilter::INFO.into()) - .from_env_lossy(), - 1 => EnvFilter::new("error,tenderdash_abci=info,drive_abci=info"), - 2 => EnvFilter::new("info,tenderdash_abci=debug,drive_abci=debug"), - 3 => EnvFilter::new("debug"), - 4 => EnvFilter::new("debug,tenderdash_abci=trace,drive_abci=trace"), - 5 => EnvFilter::new("trace"), - _ => panic!("max verbosity level is 5"), - } - } } /// Helper that initializes logging in unit tests /// /// /// For verbosity, see drive-abci --help or use 0 or 5 -pub fn init_for_tests(verbosity: u8) { +pub fn init_for_tests(level: LogLevelPreset) { let mut logger_builder = LogBuilder::new(); let config = LogConfig { - destination: "stderr".to_string(), - verbosity, + destination: LOG_DESTINATION_STDOUT.to_string(), + level, color: None, format: LogFormat::Full, max_files: 0, @@ -686,26 +764,78 @@ pub fn init_for_tests(verbosity: u8) { logger_builder .add("default", &config) .expect("cannot configure default logger"); + logger_builder.build().try_install().ok(); } -/// Verify log directory path and determine absolute path to log file. -fn log_file_path>(log_dir: T) -> Result { - let log_dir = log_dir.as_ref(); - if !log_dir.is_absolute() { +/// Verify log file path. +/// +/// Ensure that the log file path is correct, that is: +/// - it points to a file, not a directory +/// - if the log file exists, it is writable for the current user +/// - parent directory of the file exists and is writable for current user +/// - path is absolute +fn validate_log_path>(log_file_path: T) -> Result<(), Error> { + let log_file_path = log_file_path.as_ref(); + + if !log_file_path.is_absolute() { return Err(Error::FilePath( - log_dir.to_owned(), - "log path must be absolute".to_string(), + log_file_path.to_owned(), + "log file path must be absolute".to_string(), )); } - if !log_dir.is_dir() { + + if log_file_path.exists() { + // Make sure log file is writable + if log_file_path.is_dir() { + return Err(Error::FilePath( + log_file_path.to_owned(), + "log file path must point to file".to_string(), + )); + } + + let md = fs::metadata(log_file_path).map_err(|e| { + Error::FilePath( + log_file_path.to_owned(), + format!("cannot read log file metadata: {}", e), + ) + })?; + + if md.permissions().readonly() { + return Err(Error::FilePath( + log_file_path.to_owned(), + "log file is readonly".to_string(), + )); + } + } else if log_file_path.ends_with(String::from(path::MAIN_SEPARATOR)) { + // If file doesn't exist we need to do at least simple validation return Err(Error::FilePath( - log_dir.to_owned(), - "log path must point to an existing directory".to_string(), + log_file_path.to_owned(), + "log file path must point to file".to_string(), )); } - let path = log_dir.join("drive-abci.log"); - Ok(path) + + // Make sure parent directly is writable so log rotation can work + let parent_dir = log_file_path + .parent() + .expect("absolute log file path will always have parent"); + + let md = fs::metadata(parent_dir).map_err(|e| { + Error::FilePath( + log_file_path.to_owned(), + format!("cannot read parent directory: {}", e), + ) + })?; + + let permissions = md.permissions(); + if permissions.readonly() { + return Err(Error::FilePath( + log_file_path.to_owned(), + "parent directory is readonly".to_string(), + )); + } + + Ok(()) } #[cfg(test)] @@ -713,7 +843,10 @@ mod tests { use tempfile::TempDir; use super::*; - use std::str::from_utf8; + use std::fs::OpenOptions; + use std::os::unix::fs::PermissionsExt; + use std::{cmp::Ordering, fs, str::from_utf8}; + use tempfile::tempdir; /// Reads data written to provided destination. /// @@ -744,53 +877,45 @@ mod tests { #[test] fn test_logging() { let logger_stdout = LogConfig { - destination: "stdout".to_string(), - verbosity: 0, + destination: LOG_DESTINATION_STDOUT.to_string(), + level: LogLevelPreset::Info, format: LogFormat::Pretty, ..Default::default() }; let logger_stderr = LogConfig { - destination: "stderr".to_string(), - verbosity: 4, + destination: LOG_DESTINATION_STDERR.to_string(), + level: LogLevelPreset::Debug, ..Default::default() }; let logger_v0 = LogConfig { - destination: "bytes".to_string(), - verbosity: 0, + destination: LOG_DESTINATION_BYTES.to_string(), + level: LogLevelPreset::Info, ..Default::default() }; let logger_v4 = LogConfig { destination: "bytes".to_string(), - verbosity: 4, + level: LogLevelPreset::Debug, format: LogFormat::Json, ..Default::default() }; - let dir_v0 = TempDir::new().unwrap(); - let logger_dir_v0 = LogConfig { - destination: dir_v0 - .path() - .canonicalize() - .unwrap() - .to_string_lossy() - .to_string(), - verbosity: 0, + let dir = TempDir::new().unwrap(); + + let file_v0_path = dir.path().join("log.v0"); + let logger_file_v0 = LogConfig { + destination: file_v0_path.to_string_lossy().to_string(), + level: LogLevelPreset::Info, max_files: 4, ..Default::default() }; - let dir_v4 = TempDir::new().unwrap(); + let file_v4_path = dir.path().join("log.v4"); let logger_file_v4 = LogConfig { - destination: dir_v4 - .path() - .canonicalize() - .unwrap() - .to_string_lossy() - .to_string(), - verbosity: 4, + destination: file_v4_path.to_string_lossy().to_string(), + level: LogLevelPreset::Debug, max_files: 0, // no rotation ..Default::default() }; @@ -804,7 +929,7 @@ mod tests { .unwrap() .with_config("v4", &logger_v4) .unwrap() - .with_config("dir_v0", &logger_dir_v0) + .with_config("file_v0", &logger_file_v0) .unwrap() .with_config("file_v4", &logger_file_v4) .unwrap() @@ -823,9 +948,8 @@ mod tests { let result_verb_0 = dest_read_as_string(logging.0["v0"].destination.clone()); let result_verb_4 = dest_read_as_string(logging.0["v4"].destination.clone()); - let result_dir_verb_0 = dest_read_as_string(logging.0["dir_v0"].destination.clone()); + let result_dir_verb_0 = dest_read_as_string(logging.0["file_v0"].destination.clone()); - let file_v4_path = super::log_file_path(&dir_v4).unwrap(); let result_file_verb_4 = std::fs::read_to_string(&file_v4_path) .map_err(|e| panic!("{:?}: {:?}", file_v4_path.clone(), e.to_string())) .unwrap(); @@ -843,4 +967,222 @@ mod tests { assert!(result_verb_4.contains(TEST_STRING_DEBUG)); assert!(result_file_verb_4.contains(TEST_STRING_DEBUG)); } + + /// Test rotation of RotationWriter destination. + /// + /// Given that the RotationWriter is rotated 3 times, we expect to see 4 files: + /// - 1 file with the original name + /// - 3 files with the original name and timestamp suffix + #[test] + fn test_rotation_writer_rotate() { + let tempdir = TempDir::new().unwrap(); + let filepath = tempdir.path().join("drive-abci.log"); + let config = LogConfig { + destination: filepath.to_string_lossy().to_string(), + level: LogLevelPreset::Trace, + format: LogFormat::Pretty, + max_files: 3, + ..Default::default() + }; + + let loggers = LogBuilder::new() + .with_config("rotate", &config) + .expect("configure log builder") + .build(); + let logger = loggers.0.get("rotate").expect("get logger"); + + for i in 0..config.max_files + 2 { + logger + .destination + .lock() + .unwrap() + .write_all(format!("file {}\n", i).as_bytes()) + .unwrap(); + + loggers.rotate().expect("rotate logs"); + std::thread::sleep(std::time::Duration::from_millis(1100)); + } + let mut counter = 0; + tempdir.path().read_dir().unwrap().for_each(|entry| { + let entry = entry.unwrap(); + let path = entry.path(); + let path = path.to_string_lossy(); + println!("{}", path); + assert!(path.contains("drive-abci.log")); + counter += 1; + }); + assert_eq!(counter, config.max_files + 1); + } + + // TODO: Not passing on Mac OS + /// Test rotation of File destination. + /// + /// Given that we move the File and then Rotate it, we expect the file to be recreated in new location. + #[ignore] + #[test] + fn test_file_rotate() { + const ITERATIONS: usize = 4; + + let tempdir = TempDir::new().unwrap(); + let filepath = tempdir.path().join("drive-abci.log"); + let config = LogConfig { + destination: filepath.to_string_lossy().to_string(), + level: LogLevelPreset::Trace, + format: LogFormat::Pretty, + max_files: 0, + ..Default::default() + }; + + let loggers = LogBuilder::new() + .with_config("rotate", &config) + .expect("configure log builder") + .build(); + let logger = loggers.0.get("rotate").expect("get logger"); + + for i in 0..ITERATIONS { + let mut guard = logger.destination.lock().unwrap(); + guard + .write_all(format!("file {}, before rotate\n", i).as_bytes()) + .unwrap(); + + fs::rename( + &filepath, + tempdir.path().join(format!("drive-abci.log.{}", i)), + ) + .unwrap(); + // rotate() locks, so we need to drop guard here + drop(guard); + + loggers.rotate().expect("rotate logs"); + let mut guard = logger.destination.lock().unwrap(); + guard + .write_all(format!("file {}, after rotate\n", i + 1).as_bytes()) + .unwrap(); + guard.flush().unwrap(); + + std::thread::sleep(std::time::Duration::from_millis(10)); + } + + // Close all files, so that we can read them + drop(loggers); + + let mut counter = 0; + tempdir + .path() + .read_dir() + .unwrap() + .sorted_by(|a, b| { + let a = a.as_ref().unwrap().path(); + let b = b.as_ref().unwrap().path(); + if a.eq(&b) { + return Ordering::Equal; + } + if a.ends_with("drive-abci.log") { + return Ordering::Greater; + } + if b.ends_with("drive-abci.log") { + return Ordering::Greater; + } + + a.cmp(&b) + }) + .for_each(|entry| { + let entry = entry.unwrap(); + let path = entry.path(); + let path_str = path.to_string_lossy(); + let read = fs::read_to_string(&path).unwrap(); + println!("{}: {}", path_str, read); + assert!(path_str.contains("drive-abci.log")); + + if counter < ITERATIONS - 1 { + assert!( + read.contains(format!("file {}, before rotate\n", counter).as_str()), + "expect: file {}, before rotate, read: {}", + counter, + read + ) + }; + if counter > 0 { + assert!( + read.contains(format!("file {}, after rotate\n", counter).as_str()), + "expect: file {}, after rotate, read: {}", + counter, + read + ) + } + + counter = counter + 1; + }); + assert_eq!(counter, ITERATIONS + 1); + } + + #[test] + fn test_validate_log_path_file_exists_and_writable() { + let dir = tempdir().unwrap(); + let file_path = dir.path().join("log.txt"); + OpenOptions::new() + .write(true) + .create(true) + .open(&file_path) + .unwrap(); + + assert!(validate_log_path(&file_path).is_ok()); + } + + #[test] + fn test_validate_log_path_file_exists_but_readonly() { + let dir = tempdir().unwrap(); + let file_path = dir.path().join("log.txt"); + OpenOptions::new() + .write(true) + .create(true) + .open(&file_path) + .unwrap(); + let mut perms = fs::metadata(&file_path).unwrap().permissions(); + perms.set_mode(0o444); + fs::set_permissions(&file_path, perms).unwrap(); + + if let Err(Error::FilePath(_, message)) = validate_log_path(&file_path) { + assert_eq!(message, "log file is readonly"); + } else { + panic!("Expected error did not occur"); + } + } + + #[test] + fn test_validate_log_path_parent_directory_not_writable() { + let dir = tempdir().unwrap(); + let file_path = dir.path().join("log.txt"); + let mut perms = fs::metadata(dir.path()).unwrap().permissions(); + perms.set_mode(0o555); + fs::set_permissions(dir.path(), perms).unwrap(); + + if let Err(Error::FilePath(_, message)) = validate_log_path(&file_path) { + assert_eq!(message, "parent directory is readonly"); + } else { + panic!("Expected error did not occur"); + } + } + + #[test] + fn test_validate_log_path_points_to_directory() { + let dir = tempdir().unwrap(); + + if let Err(Error::FilePath(_, message)) = validate_log_path(dir.path()) { + assert_eq!(message, "log file path must point to file"); + } else { + panic!("Expected error did not occur"); + } + } + + #[test] + fn test_validate_log_path_not_absolute() { + let relative_path = Path::new("log.txt"); + + if let Err(Error::FilePath(_, message)) = validate_log_path(relative_path) { + assert_eq!(message, "log file path must be absolute"); + } else { + panic!("Expected error did not occur"); + } + } } diff --git a/packages/rs-drive-abci/src/main.rs b/packages/rs-drive-abci/src/main.rs index 9f8eb15c3df..dadc7d9d7f0 100644 --- a/packages/rs-drive-abci/src/main.rs +++ b/packages/rs-drive-abci/src/main.rs @@ -65,12 +65,10 @@ struct Cli { /// /// Repeat `v` multiple times to increase log verbosity: /// - /// * none - use RUST_LOG variable, default to `info`{n} - /// * `-v` - `info` from Drive, `error` from libraries{n} - /// * `-vv` - `debug` from Drive, `info` from libraries{n} - /// * `-vvv` - `debug` from all components{n} - /// * `-vvvv` - `trace` from Drive, `debug` from libraries{n} - /// * `-vvvvv` - `trace` from all components{n} + /// * none - use RUST_LOG variable, default to `info`{n} + /// * `-v` - `debug` from Drive, `info` from libraries{n} + /// * `-vv` - `trace` from Drive, `debug` from libraries{n} + /// * `-vvv` - `trace` from all components{n} /// /// Note: Using `-v` overrides any settings defined in RUST_LOG. /// @@ -328,7 +326,7 @@ fn configure_logging( if configs.is_empty() || cli.verbose > 0 { let cli_config = LogConfig { destination: "stderr".to_string(), - verbosity: cli.verbose, + level: cli.verbose.try_into().unwrap(), color: cli.color, ..Default::default() }; @@ -365,6 +363,7 @@ mod test { use dpp::block::epoch::Epoch; use drive::fee_pools::epochs::epoch_key_constants; + use drive_abci::logging::LogLevelPreset; use platform_version::version::PlatformVersion; use rocksdb::{IteratorMode, Options}; @@ -440,7 +439,7 @@ mod test { #[test] fn test_verify_grovedb_corrupt_0th_root() { - drive_abci::logging::init_for_tests(4); + drive_abci::logging::init_for_tests(LogLevelPreset::Silent); let tempdir = tempfile::tempdir().unwrap(); let db_path = setup_db(tempdir.path()); diff --git a/packages/rs-drive-abci/tests/strategy_tests/main.rs b/packages/rs-drive-abci/tests/strategy_tests/main.rs index 84927ce5347..9ee92c424ff 100644 --- a/packages/rs-drive-abci/tests/strategy_tests/main.rs +++ b/packages/rs-drive-abci/tests/strategy_tests/main.rs @@ -81,6 +81,7 @@ mod tests { use dpp::util::hash::hash_to_hex_string; use dpp::version::PlatformVersion; use drive_abci::config::PlatformTestConfig; + use drive_abci::logging::LogLevelPreset; use drive_abci::platform_types::platform_state::v0::PlatformStateV0Methods; use drive_abci::rpc::core::QuorumListExtendedInfo; use itertools::Itertools; @@ -1696,7 +1697,7 @@ mod tests { #[test] fn run_chain_top_up_identities() { - drive_abci::logging::init_for_tests(1); // Errors only. Use 5 to print everything + drive_abci::logging::init_for_tests(LogLevelPreset::Silent); let strategy = Strategy { contracts_with_updates: vec![], @@ -2384,7 +2385,8 @@ mod tests { #[test] fn run_chain_stop_and_restart_with_rotation() { - drive_abci::logging::init_for_tests(1); // Errors only. Use 5 to print everything + drive_abci::logging::init_for_tests(LogLevelPreset::Silent); + let strategy = Strategy { contracts_with_updates: vec![], operations: vec![],