From 4801bfcdb8121ab8cfbf04fa0d234b338298ac53 Mon Sep 17 00:00:00 2001 From: "D.S. Ljungmark" Date: Thu, 27 Jul 2023 13:16:54 +0200 Subject: [PATCH 1/3] Move connection checkin log messages to their own target Under heavy load they can happen thousands of times per second, and should generally be considered a nuisance at best. This marks the state discard as an info rather than a warning, and moves all the messages into their own log-target, so they can be filtered separately from the more relevant warnings. Signed-off-by: D.S. Ljungmark --- src/server.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/server.rs b/src/server.rs index 55444fba..62cbb3a9 100644 --- a/src/server.rs +++ b/src/server.rs @@ -1136,7 +1136,7 @@ impl Server { // server connection thrashing if clients repeatedly do this. // Instead, we ROLLBACK that transaction before putting the connection back in the pool if self.in_transaction() { - warn!("Server returned while still in transaction, rolling back transaction"); + warn!(target: "pgcat::server::cleanup", "Server returned while still in transaction, rolling back transaction"); self.query("ROLLBACK").await?; } @@ -1146,14 +1146,14 @@ impl Server { // send `DISCARD ALL` if we think the session is altered instead of just sending // it before each checkin. if self.cleanup_state.needs_cleanup() && self.cleanup_connections { - warn!("Server returned with session state altered, discarding state ({}) for application {}", self.cleanup_state, self.application_name); + info!(target: "pgcat::server::cleanup", "Server returned with session state altered, discarding state ({}) for application {}", self.cleanup_state, self.application_name); self.query("DISCARD ALL").await?; self.query("RESET ROLE").await?; self.cleanup_state.reset(); } if self.in_copy_mode() { - warn!("Server returned while still in copy-mode"); + warn!(target: "pgcat::server::cleanup", "Server returned while still in copy-mode"); } Ok(()) From 15a29463ce771dea2a811775d8c061f990cea43b Mon Sep 17 00:00:00 2001 From: "D.S. Ljungmark" Date: Thu, 27 Jul 2023 13:53:06 +0200 Subject: [PATCH 2/3] Remove left-over env_logger dependencies When moving to tracing-subscriber for logging, the env_logger dependencies were left around, this cuts them out as dead code. Signed-off-by: D.S. Ljungmark --- Cargo.lock | 38 -------------------------------------- Cargo.toml | 1 - src/main.rs | 1 - 3 files changed, 40 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9bfd4fb6..da6dcd5d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -353,19 +353,6 @@ dependencies = [ "syn 1.0.109", ] -[[package]] -name = "env_logger" -version = "0.10.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "85cdab6a89accf66733ad5a1693a4dcced6aeff64602b634530dd73c1f3ee9f0" -dependencies = [ - "humantime", - "is-terminal", - "log", - "regex", - "termcolor", -] - [[package]] name = "equivalent" version = "1.0.1" @@ -633,12 +620,6 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c4a1e36c821dbe04574f602848a19f742f4fb3c98d40449f11bcad18d6b17421" -[[package]] -name = "humantime" -version = "2.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" - [[package]] name = "hyper" version = "0.14.27" @@ -1010,7 +991,6 @@ dependencies = [ "bytes", "chrono", "clap", - "env_logger", "exitcode", "fallible-iterator", "futures", @@ -1544,15 +1524,6 @@ dependencies = [ "unicode-ident", ] -[[package]] -name = "termcolor" -version = "1.2.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "be55cf8942feac5c765c2c993422806843c9a9a45d4d5c407ad6dd2ea95eb9b6" -dependencies = [ - "winapi-util", -] - [[package]] name = "thiserror" version = "1.0.43" @@ -2028,15 +1999,6 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" -[[package]] -name = "winapi-util" -version = "0.1.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178" -dependencies = [ - "winapi", -] - [[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" diff --git a/Cargo.toml b/Cargo.toml index 5f4af313..3f87b9f5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -22,7 +22,6 @@ once_cell = "1" sqlparser = {version = "0.34", features = ["visitor"] } log = "0.4" arc-swap = "1" -env_logger = "0.10" parking_lot = "0.12.1" hmac = "0.12" sha2 = "0.10" diff --git a/src/main.rs b/src/main.rs index 916d1a8e..6c8c1654 100644 --- a/src/main.rs +++ b/src/main.rs @@ -23,7 +23,6 @@ extern crate arc_swap; extern crate async_trait; extern crate bb8; extern crate bytes; -extern crate env_logger; extern crate exitcode; extern crate log; extern crate md5; From 634f6077b7625c189e7af71ff26eb58b935ba3ab Mon Sep 17 00:00:00 2001 From: "D.S. Ljungmark" Date: Thu, 27 Jul 2023 13:53:49 +0200 Subject: [PATCH 3/3] Restore ability to filter log messages at runtime This restores the RUST_LOG filters from env_logger but now with the tracing subscriber setup. The filters are chained so commandline options mark the default in case either option is set, which should be the path of least confusion for users. ( RUST_LOG setting level to debug, and commandline to warning is an odd user case, and I don't know what a user who does that is expecting. ) It also bumps the version number as a fix to see which versions have which behaviour. Signed-off-by: D.S. Ljungmark --- Cargo.lock | 34 +++++++++++++++++++++++++++++++--- Cargo.toml | 4 ++-- src/logger.rs | 7 ++++++- 3 files changed, 39 insertions(+), 6 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index da6dcd5d..d358f0e1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -836,6 +836,15 @@ version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffbee8634e0d45d258acb448e7eaab3fce7a0a467395d4d9f228e3c1f01fb2e4" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matches" version = "0.1.10" @@ -1198,8 +1207,17 @@ checksum = "b2eae68fc220f7cf2532e4494aded17545fce192d59cd996e0fe7887f4ceb575" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.3.3", + "regex-syntax 0.7.4", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -1210,9 +1228,15 @@ checksum = "39354c10dd07468c2e73926b23bb9c2caca74c5501e38a35da70406f1d923310" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.7.4", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.7.4" @@ -1759,12 +1783,16 @@ version = "0.3.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" dependencies = [ + "matchers", "nu-ansi-term", + "once_cell", + "regex", "serde", "serde_json", "sharded-slab", "smallvec", "thread_local", + "tracing", "tracing-core", "tracing-log", "tracing-serde", diff --git a/Cargo.toml b/Cargo.toml index 3f87b9f5..c3db48aa 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "pgcat" -version = "1.1.0" +version = "1.1.1" edition = "2021" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html @@ -47,7 +47,7 @@ serde_json = "1" itertools = "0.10" clap = { version = "4.3.1", features = ["derive", "env"] } tracing = "0.1.37" -tracing-subscriber = { version = "0.3.17", features = ["json"]} +tracing-subscriber = { version = "0.3.17", features = ["json", "env-filter", "std"]} [target.'cfg(not(target_env = "msvc"))'.dependencies] jemallocator = "0.5.0" diff --git a/src/logger.rs b/src/logger.rs index c3536a0c..f9016ebf 100644 --- a/src/logger.rs +++ b/src/logger.rs @@ -1,9 +1,14 @@ use crate::cmd_args::{Args, LogFormat}; use tracing_subscriber; +use tracing_subscriber::EnvFilter; pub fn init(args: &Args) { + // Iniitalize a default filter, and then override the builtin default "warning" with our + // commandline, (default: "info") + let filter = EnvFilter::from_default_env().add_directive(args.log_level.into()); + let trace_sub = tracing_subscriber::fmt() - .with_max_level(args.log_level) + .with_env_filter(filter) .with_ansi(!args.no_color); match args.log_format {