From 62be6de9728d0119bf82108c6f3ac2b507e7a8de Mon Sep 17 00:00:00 2001 From: Vincent Ruello <5345986+vruello@users.noreply.github.com> Date: Wed, 20 Sep 2023 15:12:21 +0200 Subject: [PATCH] Split access and server logs using log4rs --- CHANGELOG.md | 1 + Cargo.lock | 177 +++++++++++++++++++++++++++++++++++-- common/src/settings.rs | 99 +++++++++++++++++++-- openwec.conf.sample.toml | 56 ++++++++++-- server/Cargo.toml | 5 +- server/src/lib.rs | 52 +++++++---- server/src/logging.rs | 153 ++++++++++++++++++++++++++++++++ server/src/main.rs | 25 +----- server/src/subscription.rs | 9 +- 9 files changed, 508 insertions(+), 69 deletions(-) create mode 100644 server/src/logging.rs diff --git a/CHANGELOG.md b/CHANGELOG.md index 48b1949..d7ed571 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,6 +25,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - `heartbeats_queue_size` now defaults to 2048 instead of 32 (#37) - **Breaking change**: Keytab file path must be specified only once for all collectors (using Kerberos authentication) - A malformed event will no longer stop the event stream (for a computer/subscription) because formatters are not allowed to fail. In problematic cases, some work is done to try to recover the raw data of the event, and an `OpenWEC.Error` field is added (in the JSON formatter) to help catch the problem (#47) +- **Breaking change**: Split access and server logs. Configuration file format has been updated. (#52) ## [0.1.0] - 2023-05-30 diff --git a/Cargo.lock b/Cargo.lock index 227e9b6..3920617 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -112,6 +112,12 @@ version = "1.0.71" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9c7d0618f0e0b7e8ff11427422b64564d5fb0be1940354bfe2e0529b18a9d9b8" +[[package]] +name = "arc-swap" +version = "1.6.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bddcadddf5e9015d310179a59bb28c4d4b9920ad0f11e8e14dbadf654890c9a6" + [[package]] name = "asn1-rs" version = "0.5.2" @@ -125,7 +131,7 @@ dependencies = [ "num-traits", "rusticata-macros", "thiserror", - "time", + "time 0.3.25", ] [[package]] @@ -297,7 +303,10 @@ checksum = "ec837a71355b28f6556dbd569b37b3f363091c0bd4b2e735674521b4c5fd9bc5" dependencies = [ "android-tzdata", "iana-time-zone", + "js-sys", "num-traits", + "time 0.1.45", + "wasm-bindgen", "winapi", ] @@ -527,6 +536,23 @@ version = "0.3.7" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7684a49fb1af197853ef7b2ee694bc1f5b4179556f1e5710e1760c5db6f5e929" +[[package]] +name = "derivative" +version = "2.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fcc3dd5e9e9c0b295d6e1e4d811fb6f157d5ffd784b8d202fc62eac8035a770b" +dependencies = [ + "proc-macro2", + "quote", + "syn 1.0.109", +] + +[[package]] +name = "destructure_traitobject" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3c877555693c14d2f84191cfd3ad8582790fc52b5e2274b40b59cf5f5cea25c7" + [[package]] name = "digest" version = "0.10.7" @@ -762,7 +788,7 @@ checksum = "be4136b2a15dd319360be1c07d9933517ccf0be8f16bf62a3bee4f0d618df427" dependencies = [ "cfg-if", "libc", - "wasi", + "wasi 0.11.0+wasi-snapshot-preview1", ] [[package]] @@ -1105,6 +1131,12 @@ dependencies = [ "vcpkg", ] +[[package]] +name = "linked-hash-map" +version = "0.5.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0717cef1bc8b636c6e1c1bbdefc09e6322da8a9321966e8928ef80d20f7f770f" + [[package]] name = "linux-raw-sys" version = "0.3.8" @@ -1126,6 +1158,41 @@ name = "log" version = "0.4.19" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b06a4cde4c0f271a446782e3eff8de789548ce57dbc8eca9292c27f4a42004b4" +dependencies = [ + "serde", +] + +[[package]] +name = "log-mdc" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a94d21414c1f4a51209ad204c1776a3d0765002c76c6abcb602a6f09f1e881c7" + +[[package]] +name = "log4rs" +version = "1.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d36ca1786d9e79b8193a68d480a0907b612f109537115c6ff655a3a1967533fd" +dependencies = [ + "anyhow", + "arc-swap", + "chrono", + "derivative", + "fnv", + "humantime", + "libc", + "log", + "log-mdc", + "parking_lot", + "serde", + "serde-value", + "serde_json", + "serde_yaml", + "thiserror", + "thread-id", + "typemap-ors", + "winapi", +] [[package]] name = "lz4-sys" @@ -1180,7 +1247,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "927a765cd3fc26206e66b296465fa9d3e5ab003e651c1b3c060e7956d96b19d2" dependencies = [ "libc", - "wasi", + "wasi 0.11.0+wasi-snapshot-preview1", "windows-sys", ] @@ -1317,6 +1384,15 @@ dependencies = [ "vcpkg", ] +[[package]] +name = "ordered-float" +version = "2.10.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7940cf2ca942593318d07fcf2596cdca60a85c9e7fab408a5e21a4f9dcd40d87" +dependencies = [ + "num-traits", +] + [[package]] name = "parking_lot" version = "0.12.1" @@ -1335,7 +1411,7 @@ checksum = "93f00c865fe7cabf650081affecd3871070f26767e7b2070a3ffae14c654b447" dependencies = [ "cfg-if", "libc", - "redox_syscall", + "redox_syscall 0.3.5", "smallvec", "windows-targets", ] @@ -1556,6 +1632,15 @@ dependencies = [ "url", ] +[[package]] +name = "redox_syscall" +version = "0.2.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fb5a58c1855b4b6819d59012155603f0b22ad30cad752600aadfcb695265519a" +dependencies = [ + "bitflags 1.3.2", +] + [[package]] name = "redox_syscall" version = "0.3.5" @@ -1735,6 +1820,16 @@ dependencies = [ "serde_derive", ] +[[package]] +name = "serde-value" +version = "0.7.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f3a1a3341211875ef120e117ea7fd5228530ae7e7036a779fdc9117be6b3282c" +dependencies = [ + "ordered-float", + "serde", +] + [[package]] name = "serde_derive" version = "1.0.164" @@ -1766,6 +1861,18 @@ dependencies = [ "serde", ] +[[package]] +name = "serde_yaml" +version = "0.8.26" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "578a7433b776b56a35785ed5ce9a7e777ac0598aac5a6dd1b4b18a307c7fc71b" +dependencies = [ + "indexmap 1.9.3", + "ryu", + "serde", + "yaml-rust", +] + [[package]] name = "serial_test" version = "2.0.0" @@ -1803,7 +1910,6 @@ dependencies = [ "chrono", "clap", "common", - "env_logger", "futures", "futures-util", "hex", @@ -1815,6 +1921,8 @@ dependencies = [ "lazy_static", "libgssapi", "log", + "log-mdc", + "log4rs", "mime", "quick-xml", "rdkafka", @@ -1989,7 +2097,7 @@ dependencies = [ "autocfg", "cfg-if", "fastrand", - "redox_syscall", + "redox_syscall 0.3.5", "rustix", "windows-sys", ] @@ -2023,6 +2131,28 @@ dependencies = [ "syn 2.0.28", ] +[[package]] +name = "thread-id" +version = "4.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3ee93aa2b8331c0fec9091548843f2c90019571814057da3b783f9de09349d73" +dependencies = [ + "libc", + "redox_syscall 0.2.16", + "winapi", +] + +[[package]] +name = "time" +version = "0.1.45" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1b797afad3f312d1c66a56d11d0316f916356d11bd158fbc6ca6389ff6bf805a" +dependencies = [ + "libc", + "wasi 0.10.0+wasi-snapshot-preview1", + "winapi", +] + [[package]] name = "time" version = "0.3.25" @@ -2259,6 +2389,15 @@ version = "0.2.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3528ecfd12c466c6f163363caf2d02a71161dd5e1cc6ae7b34207ea2d42d81ed" +[[package]] +name = "typemap-ors" +version = "1.0.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a68c24b707f02dd18f1e4ccceb9d49f2058c2fb86384ef9972592904d7a28867" +dependencies = [ + "unsafe-any-ors", +] + [[package]] name = "typenum" version = "1.16.0" @@ -2292,6 +2431,15 @@ version = "0.2.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f962df74c8c05a667b5ee8bcf162993134c104e96440b663c8daa176dc772d8c" +[[package]] +name = "unsafe-any-ors" +version = "1.0.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e0a303d30665362d9680d7d91d78b23f5f899504d4f08b3c4cf08d055d87c0ad" +dependencies = [ + "destructure_traitobject", +] + [[package]] name = "untrusted" version = "0.7.1" @@ -2346,6 +2494,12 @@ dependencies = [ "try-lock", ] +[[package]] +name = "wasi" +version = "0.10.0+wasi-snapshot-preview1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1a143597ca7c7793eff794def352d41792a93c481eb1042423ff7ff72ba2c31f" + [[package]] name = "wasi" version = "0.11.0+wasi-snapshot-preview1" @@ -2565,7 +2719,7 @@ dependencies = [ "oid-registry", "rusticata-macros", "thiserror", - "time", + "time 0.3.25", ] [[package]] @@ -2574,6 +2728,15 @@ version = "0.13.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4d25c75bf9ea12c4040a97f829154768bbbce366287e2dc044af160cd79a13fd" +[[package]] +name = "yaml-rust" +version = "0.4.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "56c1936c4cc7a1c9ab21a1ebb602eb942ba868cbd44a99cb7cdc5892335e1c85" +dependencies = [ + "linked-hash-map", +] + [[package]] name = "zstd-sys" version = "2.0.8+zstd.1.5.5" diff --git a/common/src/settings.rs b/common/src/settings.rs index 822e1e3..b0822b6 100644 --- a/common/src/settings.rs +++ b/common/src/settings.rs @@ -1,4 +1,4 @@ -use anyhow::Result; +use anyhow::{Error, Result}; use serde::Deserialize; use std::str::FromStr; use std::{fs::File, io::Read}; @@ -180,9 +180,70 @@ impl Postgres { } } +#[derive(Debug, Deserialize, Clone, PartialEq, Eq)] +pub enum LoggingType { + Stdout, + Stderr, + File(String), +} + +impl FromStr for LoggingType { + type Err = Error; + + fn from_str(s: &str) -> std::result::Result { + let s_lower = s.to_lowercase(); + if s_lower == "stdout" { + Ok(LoggingType::Stdout) + } else if s_lower == "stderr" { + Ok(LoggingType::Stderr) + } else { + Ok(LoggingType::File(s.to_owned())) + } + } +} + #[derive(Debug, Deserialize, Clone)] -pub struct Server { +pub struct Logging { verbosity: Option, + access_logs: Option, + access_logs_pattern: Option, + server_logs: Option, + server_logs_pattern: Option, +} + +impl Logging { + pub fn verbosity(&self) -> Option<&String> { + self.verbosity.as_ref() + } + + pub fn access_logs(&self) -> Option { + // Access logs defaults to None (don't log access) + self.access_logs + .as_ref() + .map(|s| LoggingType::from_str(s).expect("Can not happen")) + } + + pub fn server_logs(&self) -> LoggingType { + match &self.server_logs { + Some(s) => LoggingType::from_str(s).expect("Can not happen"), + None => LoggingType::Stderr, + } + } + + pub fn access_logs_pattern(&self) -> String { + match &self.access_logs_pattern { + Some(s) => s.to_owned(), + None => "{X(ip)}:{X(port)} - {X(principal)} [{d}] \"{X(http_uri)}\" {X(http_status)} {X(response_time)}{n}".to_owned() + } + } + + pub fn server_logs_pattern(&self) -> Option<&String> { + self.server_logs_pattern.as_ref() + } +} + +#[derive(Debug, Deserialize, Clone)] +pub struct Server { db_sync_interval: Option, flush_heartbeats_interval: Option, heartbeats_queue_size: Option, @@ -191,10 +252,6 @@ pub struct Server { } impl Server { - pub fn verbosity(&self) -> Option<&String> { - self.verbosity.as_ref() - } - pub fn db_sync_interval(&self) -> u64 { self.db_sync_interval.unwrap_or(5) } @@ -221,6 +278,7 @@ pub struct Settings { collectors: Vec, database: Database, server: Server, + logging: Logging, } impl std::str::FromStr for Settings { @@ -250,6 +308,10 @@ impl Settings { pub fn server(&self) -> &Server { &self.server } + + pub fn logging(&self) -> &Logging { + &self.logging + } } #[cfg(test)] @@ -258,9 +320,12 @@ mod tests { const CONFIG_KERBEROS_SQLITE: &str = r#" [server] - verbosity = "debug" keytab = "wec.windomain.local.keytab" + [logging] + verbosity = "debug" + server_logs = "stdout" + [database] type = "SQLite" path = "/tmp/toto.sqlite" @@ -302,12 +367,20 @@ mod tests { }; assert_eq!(sqlite.path(), "/tmp/toto.sqlite"); - assert_eq!(s.server().verbosity().unwrap(), "debug"); + + assert_eq!(s.logging().verbosity().unwrap(), "debug"); + assert!(s.logging().access_logs().is_none()); + assert_eq!(s.logging().server_logs(), LoggingType::Stdout); } const CONFIG_TLS_POSTGRES: &str = r#" [server] + [logging] + access_logs = "/tmp/toto" + server_logs_pattern = "toto" + access_logs_pattern = "tutu" + [database] type = "Postgres" host = "localhost" @@ -356,6 +429,14 @@ mod tests { assert_eq!(postgres.dbname(), "test"); assert_eq!(postgres.user(), "root"); assert_eq!(postgres.password(), ""); - assert!(s.server().verbosity().is_none()); + + assert!(s.logging().verbosity().is_none()); + assert_eq!( + s.logging().access_logs(), + Some(LoggingType::File("/tmp/toto".to_string())) + ); + assert_eq!(s.logging().server_logs(), LoggingType::Stderr,); + assert_eq!(s.logging().server_logs_pattern().unwrap(), "toto"); + assert_eq!(s.logging().access_logs_pattern(), "tutu"); } } diff --git a/openwec.conf.sample.toml b/openwec.conf.sample.toml index 57fc85b..311ca8e 100644 --- a/openwec.conf.sample.toml +++ b/openwec.conf.sample.toml @@ -3,12 +3,6 @@ ####################### [server] -# [Optional] -# Set server logging verbosity -# This parameter is overwritten by --verbosity argument and -# the OPENWEC_LOG environment variable. -# Default value is warn -# verbosity = "warn" # [Optional] # Set subscriptions refresh interval @@ -52,6 +46,56 @@ # It can contain other entries that aren't used by openwec. # keytab = "/etc/krb5.keytab" +########################## +## Logging settings ## +########################## + +[logging] + +# [Optional] +# Set server logging verbosity +# This parameter is overwritten by --verbosity argument. +# Default value is warn +# Possible values are: error, warn, info, debug, trace +# verbosity = "warn" + +# [Optional] +# Server logs destination, can be : +# - stdin +# - stderr +# - : logs will be stored in the given file +# Default value is stderr +# server_logs = stderr + +# [Optional] +# Server log formatting pattern +# Pattern syntax is explained here: https://docs.rs/log4rs/latest/log4rs/encode/pattern +# Default value is None, meaning "{d} {l} {t} - {m}{n}" +# server_logs_pattern = None + +# [Optional] +# Access logs destination, can be : +# - stdin +# - stderr +# - : logs will be stored in the given file +# - None: disable access logs +# Default value is None +# access_logs = None + +# [Optional] +# Access log formatting pattern +# Pattern syntax is explained here: https://docs.rs/log4rs/latest/log4rs/encode/pattern +# Contextual information can be accessed using {X()}. Available values are: +# - http_status +# - http_method +# - http_uri +# - response_time (in ms) +# - ip +# - port +# - principal +# Default value is None, meaning "{X(ip)}:{X(port)} - {X(principal)} [{d}] \"{X(http_uri)}\" {X(http_status)} {X(response_time)}{n}" +# access_logs_pattern = None + ########################## ## Databases settings ## ########################## diff --git a/server/Cargo.toml b/server/Cargo.toml index 07c1297..8644171 100644 --- a/server/Cargo.toml +++ b/server/Cargo.toml @@ -11,7 +11,6 @@ path = "src/main.rs" [dependencies] common = { path = "../common" } -env_logger = "0.10.0" anyhow = "1.0.71" base64 = "0.21.2" buf-read-ext = "0.4.0" @@ -46,4 +45,6 @@ tokio-rustls = "0.24.1" x509-parser = "0.15.1" sha1 = "0.10.5" hex = "0.4.3" -redis = { version = "0.23.3", features = ["tokio-comp", "aio"]} \ No newline at end of file +redis = { version = "0.23.3", features = ["tokio-comp", "aio"]} +log4rs = "1.2.0" +log-mdc = "0.1.0" diff --git a/server/src/lib.rs b/server/src/lib.rs index 6e9e8c6..152fbce 100644 --- a/server/src/lib.rs +++ b/server/src/lib.rs @@ -2,6 +2,7 @@ mod event; mod formatter; mod heartbeat; mod kerberos; +mod logging; mod logic; mod multipart; mod output; @@ -53,6 +54,7 @@ use tokio::sync::{mpsc, oneshot}; use tokio_rustls::server::TlsStream; use tokio_rustls::TlsAcceptor; +use crate::logging::ACCESS_LOGGER; use crate::tls::{make_config, subject_from_cert}; pub enum RequestCategory { @@ -293,17 +295,28 @@ async fn handle_payload( } } -fn log_response(addr: &SocketAddr, method: &str, uri: &str, start: &Instant, status: StatusCode) { +fn log_response( + addr: &SocketAddr, + method: &str, + uri: &str, + start: &Instant, + status: StatusCode, + principal: &str, +) { let duration: f32 = start.elapsed().as_micros() as f32; - info!( - "Responded status {} to {}:{} (request was {}:{}) in {:.3}ms", - status, - addr.ip(), - addr.port(), - method, - uri, - duration / 1000.0 - ); + // MDC is thread related, so it should be safe to use it in a non-async + // function. + log_mdc::insert("http_status", status.as_str()); + log_mdc::insert("http_method", method); + log_mdc::insert("http_uri", uri); + log_mdc::insert("response_time", format!("{:.3}", duration / 1000.0)); + log_mdc::insert("ip", addr.ip().to_string()); + log_mdc::insert("port", addr.port().to_string()); + log_mdc::insert("principal", principal); + + // Empty message, logging pattern should use MDC + info!(target: ACCESS_LOGGER, ""); + log_mdc::clear(); } async fn handle( @@ -342,7 +355,7 @@ async fn handle( e ); let status = StatusCode::UNAUTHORIZED; - log_response(&addr, &method, &uri, &start, status); + log_response(&addr, &method, &uri, &start, status, "-"); return Ok(Response::builder() .status(status) .body(Body::empty()) @@ -357,7 +370,7 @@ async fn handle( Err(e) => { error!("Failed to compute request data: {:?}", e); let status = StatusCode::NOT_FOUND; - log_response(&addr, &method, &uri, &start, status); + log_response(&addr, &method, &uri, &start, status, &principal); return Ok(Response::builder() .status(status) .body(Body::empty()) @@ -371,7 +384,7 @@ async fn handle( Err(e) => { error!("Failed to retrieve request payload: {:?}", e); let status = StatusCode::BAD_REQUEST; - log_response(&addr, &method, &uri, &start, status); + log_response(&addr, &method, &uri, &start, status, &principal); return Ok(Response::builder() .status(status) .body(Body::empty()) @@ -401,7 +414,7 @@ async fn handle( Err(e) => { error!("Failed to compute a response payload to request: {:?}", e); let status = StatusCode::INTERNAL_SERVER_ERROR; - log_response(&addr, &method, &uri, &start, status); + log_response(&addr, &method, &uri, &start, status, &principal); return Ok(Response::builder() .status(status) .body(Body::empty()) @@ -422,7 +435,7 @@ async fn handle( Err(e) => { error!("Failed to build HTTP response: {:?}", e); let status = StatusCode::INTERNAL_SERVER_ERROR; - log_response(&addr, &method, &uri, &start, status); + log_response(&addr, &method, &uri, &start, status, &principal); return Ok(Response::builder() .status(status) .body(Body::empty()) @@ -430,7 +443,7 @@ async fn handle( } }; - log_response(&addr, &method, &uri, &start, response.status()); + log_response(&addr, &method, &uri, &start, response.status(), &principal); Ok(response) } @@ -593,7 +606,12 @@ async fn shutdown_signal() { }; } -pub async fn run(settings: Settings) { +pub async fn run(settings: Settings, verbosity: u8) { + // Initialize loggers + if let Err(e) = logging::init(&settings, verbosity) { + panic!("Failed to setup logging: {:?}", e); + } + // XXX : because the 2 closures have different types we use this, but may be better way to do this let mut servers: Vec> + Send>>> = Vec::new(); diff --git a/server/src/logging.rs b/server/src/logging.rs new file mode 100644 index 0000000..de410b6 --- /dev/null +++ b/server/src/logging.rs @@ -0,0 +1,153 @@ +use std::str::FromStr; + +use anyhow::{Context, Result}; +use common::settings::{LoggingType, Settings}; +use log::{info, warn, LevelFilter}; +use log4rs::{ + append::{ + console::{ConsoleAppender, Target}, + file::FileAppender, + Append, + }, + config::{Appender, Logger, Root}, + encode::pattern::PatternEncoder, + Config, Handle, +}; +use tokio::signal::unix::{signal, SignalKind}; + +pub static ACCESS_LOGGER: &str = "access"; +pub static SERVER_LOGGER: &str = "server"; + +pub fn init(settings: &Settings, verbosity: u8) -> Result<()> { + let config = create_config(settings, verbosity)?; + let handle = log4rs::init_config(config).unwrap(); + + let settings_owned = settings.clone(); + + // Loggers are reloaded when a SIGHUP signal is received + // This is required by utilities like logrotate + tokio::spawn(async move { reload_loggers(handle, settings_owned, verbosity).await }); + Ok(()) +} + +fn create_appender( + logging_type: &LoggingType, + pattern_opt: Option<&String>, +) -> Result> { + let encoder = if let Some(pattern) = pattern_opt { + Box::new(PatternEncoder::new(pattern)) + } else { + Box::::default() + }; + match logging_type { + LoggingType::Stdout => Ok(Box::new( + ConsoleAppender::builder() + .encoder(encoder) + .target(Target::Stdout) + .build(), + )), + LoggingType::Stderr => Ok(Box::new( + ConsoleAppender::builder() + .encoder(encoder) + .target(Target::Stderr) + .build(), + )), + LoggingType::File(path) => { + let appender = FileAppender::builder() + .encoder(encoder) + .append(true) + .build(path) + .context("Failed to create FileAppender")?; + Ok(Box::new(appender)) + } + } +} + +fn get_level_filter(verbosity_arg_count: u8, verbosity_setting: Option<&String>) -> LevelFilter { + if verbosity_arg_count > 0 { + match verbosity_arg_count { + 1 => LevelFilter::Info, + 2 => LevelFilter::Debug, + _ => LevelFilter::Trace, + } + } else if let Some(verbosity) = verbosity_setting { + LevelFilter::from_str(verbosity).unwrap_or_else(|err| { + eprintln!( + "Could not parse verbosity level \"{}\": {}. Fallback to \"warn\".", + verbosity, err + ); + LevelFilter::Warn + }) + } else { + LevelFilter::Warn + } +} + +fn create_config(settings: &Settings, verbosity_arg_count: u8) -> Result { + let mut builder = Config::builder(); + + builder = builder.appender( + Appender::builder().build( + SERVER_LOGGER, + create_appender( + &settings.logging().server_logs(), + settings.logging().server_logs_pattern(), + ) + .context("Could not create server logger")?, + ), + ); + + if let Some(access_logs) = settings.logging().access_logs() { + // Configure access logging + // Access logs level is always "info" + builder = builder + .appender( + Appender::builder().build( + ACCESS_LOGGER, + create_appender( + &access_logs, + Some(&settings.logging().access_logs_pattern()), + ) + .context("Could not create access logger")?, + ), + ) + .logger( + Logger::builder() + .appender(ACCESS_LOGGER) + .additive(false) + .build(ACCESS_LOGGER, LevelFilter::Info), + ); + } else { + // Deactivate access logs (levelFilter::Off) + builder = builder.logger( + Logger::builder() + .appender(SERVER_LOGGER) + .additive(false) + .build(ACCESS_LOGGER, LevelFilter::Off), + ); + } + + builder + .build( + Root::builder() + .appender(SERVER_LOGGER) + .build(get_level_filter( + verbosity_arg_count, + settings.logging().verbosity(), + )), + ) + .context("Could not build logger config") +} + +async fn reload_loggers(handle: Handle, settings: Settings, verbosity_arg_count: u8) { + let mut sighup = signal(SignalKind::hangup()).expect("Could not listen to SIGHUP"); + + loop { + sighup.recv().await; + match create_config(&settings, verbosity_arg_count) { + Ok(c) => handle.set_config(c), + Err(e) => warn!("Could not reload logger: {:?}", e), + }; + info!("Logger config reloaded"); + } +} diff --git a/server/src/main.rs b/server/src/main.rs index e6528b7..3979248 100644 --- a/server/src/main.rs +++ b/server/src/main.rs @@ -1,5 +1,6 @@ use clap::{arg, command}; use common::settings::{Settings, DEFAULT_CONFIG_FILE}; + use server::run; use std::env; @@ -24,27 +25,7 @@ async fn main() { } }; - if env::var("OPENWEC_LOG").is_err() { - if matches.get_count("verbosity") > 0 { - env::set_var( - "OPENWEC_LOG", - match matches.get_count("verbosity") { - 1 => "info", - 2 => "debug", - _ => "trace", - }, - ); - } else if let Some(verbosity) = settings.server().verbosity() { - env::set_var("OPENWEC_LOG", verbosity); - } else { - env::set_var("OPENWEC_LOG", "warn"); - } - } - - env_logger::Builder::from_env("OPENWEC_LOG") - .format_module_path(false) - .format_timestamp(None) - .init(); + let verbosity = matches.get_count("verbosity"); - run(settings).await; + run(settings, verbosity).await; } diff --git a/server/src/subscription.rs b/server/src/subscription.rs index d835d6f..5bab460 100644 --- a/server/src/subscription.rs +++ b/server/src/subscription.rs @@ -116,7 +116,7 @@ pub async fn reload_subscriptions_task( } }, _ = sighup.recv() => { - debug!("Update subscriptions from db (signal)"); + info!("Update subscriptions from db (signal)"); if let Err(e) = reload_subscriptions(db.clone(), subscriptions.clone(), false).await { warn!("Failed to update subscriptions on SIGHUP: {:?}", e); continue; @@ -200,10 +200,7 @@ async fn reload_subscriptions( info!("Subscription {} has been updated", subscription_data.uuid()); mem_subscriptions.remove(old_subscription.version()); } else { - info!( - "New subscription {} has been created", - subscription_data.uuid() - ); + info!("Subscription {} has been created", subscription_data.uuid()); } // Initialize the new subscription and add it to in-memory subscriptions @@ -237,7 +234,7 @@ async fn reload_subscriptions( if mem_subscriptions.is_empty() { warn!("There are no active subscriptions!"); } else { - info!( + debug!( "Active subscriptions are: {}", mem_subscriptions .iter()