Added a bash script to check the log format. (#4150)

Author: fulmicoton

CODE_STYLE.md

@@ -109,15 +109,26 @@ These assert will not be part of the release binary and won't hurt the execution
 
 **example needed**
 
-## Errors
+## Errors and log messages
 
-Error messages should be concise, lowercase (except proper names), and without trailing punctuation.
+Error and log messages follow the same format. They should be concise, lowercase (except proper names), and without trailing punctuation.
 
-### Examples
+As a loose rule, where it does not hurt readability, log messages should rely on `tracing` 
+structured logging instead of templating. 
+
+In other words, prefer:
+`warn!(remaining=remaining_attempts, "trubulizor rpc plane retry failed")`
+to 
+`warn!("trubulizor rpc plane retry failed ({remaining_attempts} attempts remaining)")`
+
+### Error Examples
 - "failed to start actor runtimes"
 - "cannot join PostgreSQL URI {} with path {:?}"
 - "could not find split metadata in Metastore {}"
-- "unkown output format {:?}"
+- "unknown output format {:?}"
+ 
+### Log examples
+
 
 ## Comments
 

quickwit/Makefile

@@ -6,6 +6,8 @@ fmt:
 	@(rustup toolchain list | ( ! grep -q nightly && echo "Toolchain 'nightly' is not installed. Please install using 'rustup toolchain install nightly'.") ) || cargo +nightly fmt
 	@echo "Checking license headers"
 	@bash scripts/check_license_headers.sh
+	@echo "Checking log format"
+	@bash scripts/check_log_format.sh
 
 fix:
 	@echo "Running cargo clippy --fix"

quickwit/quickwit-actors/src/lib.rs

@@ -60,8 +60,7 @@ pub use observation::{Observation, ObservationType};
 use quickwit_common::KillSwitch;
 pub use spawn_builder::SpawnContext;
 use thiserror::Error;
-use tracing::info;
-use tracing::log::warn;
+use tracing::{info, warn};
 pub use universe::Universe;
 
 pub use self::actor_context::ActorContext;
@@ -93,19 +92,19 @@ fn heartbeat_from_env_or_default() -> Duration {
     match std::env::var("QW_ACTOR_HEARTBEAT_SECS") {
         Ok(actor_hearbeat_secs_str) => {
             if let Ok(actor_hearbeat_secs) = actor_hearbeat_secs_str.parse::<NonZeroU64>() {
-                info!("Set the actor heartbeat to {actor_hearbeat_secs} seconds.");
+                info!("set the actor heartbeat to {actor_hearbeat_secs} seconds");
                 return Duration::from_secs(actor_hearbeat_secs.get());
             } else {
                 warn!(
-                    "Failed to parse `QW_ACTOR_HEARTBEAT_SECS={actor_hearbeat_secs_str}` in \
-                     seconds > 0, using default heartbeat (30 seconds)."
+                    "failed to parse `QW_ACTOR_HEARTBEAT_SECS={actor_hearbeat_secs_str}` in \
+                     seconds > 0, using default heartbeat (30 seconds)"
                 );
             };
         }
         Err(std::env::VarError::NotUnicode(os_str)) => {
             warn!(
-                "Failed to parse `QW_ACTOR_HEARTBEAT_SECS={os_str:?}` in a valid unicode string, \
-                 using default heartbeat (30 seconds)."
+                "failed to parse `QW_ACTOR_HEARTBEAT_SECS={os_str:?}` in a valid unicode string, \
+                 using default heartbeat (30 seconds)"
             );
         }
         Err(std::env::VarError::NotPresent) => {}

quickwit/quickwit-cli/src/jemalloc.rs

@@ -59,7 +59,7 @@ pub async fn jemalloc_metrics_loop() -> tikv_jemalloc_ctl::Result<()> {
 pub fn start_jemalloc_metrics_loop() {
     tokio::task::spawn(async {
         if let Err(jemalloc_metrics_err) = jemalloc_metrics_loop().await {
-            error!(err=?jemalloc_metrics_err, "Failed to gather metrics from jemalloc.");
+            error!(err=?jemalloc_metrics_err, "failed to gather metrics from jemalloc");
         }
     });
 }

quickwit/quickwit-cli/src/lib.rs

@@ -222,7 +222,7 @@ async fn load_node_config(config_uri: &Uri) -> anyhow::Result<NodeConfig> {
     let config = NodeConfig::load(config_format, config_content.as_slice())
         .await
         .with_context(|| format!("failed to parse node config `{config_uri}`"))?;
-    info!(config_uri=%config_uri, config=?config, "Loaded node config.");
+    info!(config_uri=%config_uri, config=?config, "loaded node config");
     Ok(config)
 }
 
@@ -402,10 +402,10 @@ pub mod busy_detector {
 
         let suppressed = SUPPRESSED_DEBUG_COUNT.swap(0, Ordering::Relaxed);
         if suppressed == 0 {
-            debug!("Thread wasn't parked for {delta}µs, is the runtime too busy?");
+            debug!("thread wasn't parked for {delta}µs, is the runtime too busy?");
         } else {
             debug!(
-                "Thread wasn't parked for {delta}µs, is the runtime too busy? ({suppressed} \
+                "thread wasn't parked for {delta}µs, is the runtime too busy? ({suppressed} \
                  similar messages suppressed)"
             );
         }

quickwit/quickwit-cli/src/service.rs

@@ -81,7 +81,7 @@ impl RunCliCommand {
         crate::busy_detector::set_enabled(true);
 
         if let Some(services) = &self.services {
-            tracing::info!(services = %services.iter().join(", "), "Setting services from override.");
+            tracing::info!(services = %services.iter().join(", "), "setting services from override");
             node_config.enabled_services = services.clone();
         }
         let telemetry_handle_opt =

quickwit/quickwit-cli/src/tool.rs

@@ -630,12 +630,12 @@ pub async fn merge_cli(args: MergeArgs) -> anyhow::Result<()> {
         let observation = pipeline_handle.last_observation();
 
         if observation.num_ongoing_merges == 0 {
-            info!("Merge pipeline has no more ongoing merges, Exiting.");
+            info!("merge pipeline has no more ongoing merges, exiting");
             break;
         }
 
         if pipeline_handle.state().is_exit() {
-            info!("Merge pipeline has exited, Exiting.");
+            info!("merge pipeline has exited, exiting");
             break;
         }
     }

quickwit/quickwit-cli/tests/helpers.rs

@@ -158,7 +158,7 @@ impl TestEnv {
         };
         tokio::spawn(async move {
             if let Err(error) = run_command.execute().await {
-                error!(err=?error, "Failed to start a quickwit server.");
+                error!(err=?error, "failed to start a quickwit server");
             }
         });
         wait_for_server_ready(([127, 0, 0, 1], self.rest_listen_port).into()).await?;

quickwit/quickwit-cluster/src/member.rs

@@ -122,7 +122,7 @@ fn parse_indexing_cpu_capacity(node_state: &NodeState) -> CpuCapacity {
     if let Ok(indexing_capacity) = CpuCapacity::from_str(indexing_capacity_str) {
         indexing_capacity
     } else {
-        error!(indexing_capacity=?indexing_capacity_str, "Received an unparseable indexing capacity from node.");
+        error!(indexing_capacity=?indexing_capacity_str, "received an unparseable indexing capacity from node");
         CpuCapacity::zero()
     }
 }

quickwit/quickwit-common/src/runtimes.rs

@@ -120,7 +120,7 @@ impl RuntimeType {
             .get_or_init(|| {
                 #[cfg(any(test, feature = "testsuite"))]
                 {
-                    tracing::warn!("Starting Tokio actor runtimes for tests.");
+                    tracing::warn!("starting Tokio actor runtimes for tests");
                     start_runtimes(RuntimesConfig::light_for_tests())
                 }
                 #[cfg(not(any(test, feature = "testsuite")))]