From 328108aeb588747e0c9a8276bf0201ab7564908c Mon Sep 17 00:00:00 2001 From: Spindel Ljungmark Date: Thu, 27 Jul 2023 17:51:23 +0200 Subject: [PATCH 1/4] Restore the ability to filter spammy log messages (#530) * 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 * 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 * 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 --------- Signed-off-by: D.S. Ljungmark --- Cargo.lock | 72 ++++++++++++++++++++++----------------------------- Cargo.toml | 5 ++-- src/logger.rs | 7 ++++- src/main.rs | 1 - src/server.rs | 6 ++--- 5 files changed, 42 insertions(+), 49 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9bfd4fb6..d358f0e1 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" @@ -855,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" @@ -1010,7 +1000,6 @@ dependencies = [ "bytes", "chrono", "clap", - "env_logger", "exitcode", "fallible-iterator", "futures", @@ -1218,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]] @@ -1230,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" @@ -1544,15 +1548,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" @@ -1788,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", @@ -2028,15 +2027,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..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 @@ -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" @@ -48,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 { 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; 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 9d1c46a3e9a672d3bb2709ded8a814c5f07fa8b8 Mon Sep 17 00:00:00 2001 From: Bertrand Paquet Date: Fri, 28 Jul 2023 09:31:53 +0200 Subject: [PATCH 2/4] Fix typo in the config documentation (#532) --- CONFIG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CONFIG.md b/CONFIG.md index 3118a49a..c60e1562 100644 --- a/CONFIG.md +++ b/CONFIG.md @@ -230,7 +230,7 @@ default: "random" Load balancing mode `random` selects the server at random -`loc` selects the server with the least outstanding busy conncetions +`loc` selects the server with the least outstanding busy connections ### default_role ``` From aefcf4281c6c33532d73c0578d3fba1c8f9a5d11 Mon Sep 17 00:00:00 2001 From: Lev Kokotov Date: Tue, 1 Aug 2023 17:46:34 -0700 Subject: [PATCH 3/4] Fix for #534 and #535 --- Cargo.lock | 2 +- pgcat.toml | 2 +- src/server.rs | 10 +++++++--- 3 files changed, 9 insertions(+), 5 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d358f0e1..ec849329 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -990,7 +990,7 @@ checksum = "9b2a4787296e9989611394c33f193f676704af1686e70b8f8033ab5ba9a35a94" [[package]] name = "pgcat" -version = "1.1.0" +version = "1.1.1" dependencies = [ "arc-swap", "async-trait", diff --git a/pgcat.toml b/pgcat.toml index 3e8801b6..d8ed1088 100644 --- a/pgcat.toml +++ b/pgcat.toml @@ -270,7 +270,7 @@ username = "sharding_user" # if `server_password` is not set. password = "sharding_user" -pool_mode = "session" +pool_mode = "transaction" # PostgreSQL username used to connect to the server. # server_username = "another_user" diff --git a/src/server.rs b/src/server.rs index 62cbb3a9..bb453aa4 100644 --- a/src/server.rs +++ b/src/server.rs @@ -997,7 +997,9 @@ impl Server { } } - self.deallocate(names).await?; + if !names.is_empty() { + self.deallocate(names).await?; + } Ok(()) } @@ -1013,7 +1015,7 @@ impl Server { /// Close a prepared statement on the server. pub async fn deallocate(&mut self, names: Vec) -> Result<(), Error> { for name in &names { - debug!("Deallocating prepared statement `{}`", name); + info!("Deallocating prepared statement `{}`", name); let close = Close::new(name); let bytes: BytesMut = close.try_into()?; @@ -1021,7 +1023,9 @@ impl Server { self.send(&bytes).await?; } - self.send(&flush()).await?; + if !names.is_empty() { + self.send(&flush()).await?; + } // Read and discard CloseComplete (3) for name in &names { From 1f2c6507f7fb5461df1a599c0b380aa114597bb5 Mon Sep 17 00:00:00 2001 From: Lev Kokotov Date: Tue, 1 Aug 2023 17:47:34 -0700 Subject: [PATCH 4/4] debug -> release --- src/server.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/server.rs b/src/server.rs index bb453aa4..afa1c09d 100644 --- a/src/server.rs +++ b/src/server.rs @@ -1015,7 +1015,7 @@ impl Server { /// Close a prepared statement on the server. pub async fn deallocate(&mut self, names: Vec) -> Result<(), Error> { for name in &names { - info!("Deallocating prepared statement `{}`", name); + debug!("Deallocating prepared statement `{}`", name); let close = Close::new(name); let bytes: BytesMut = close.try_into()?;