Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
43 changes: 23 additions & 20 deletions backend/windmill-common/src/tracing_init.rs
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,25 @@ fn compact_layer<S>() -> Layer<S, format::DefaultFields, format::Format<format::

lazy_static::lazy_static! {
pub static ref JSON_FMT: bool = std::env::var("JSON_FMT").map(|x| x == "true").unwrap_or(false);
pub static ref QUIET_MODE: bool = std::env::var("QUIET").map(|x| x == "true" || x == "1").unwrap_or(false);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's an existing QUIET_LOGS environment variable defined in windmill-common/src/lib.rs:171 that also controls log verbosity. Having both QUIET and QUIET_LOGS could confuse users.

Consider either:

  1. Reusing QUIET_LOGS for this feature
  2. Documenting the difference clearly (e.g., QUIET_LOGS for conditional code checks vs QUIET for tracing filter)
  3. Consolidating both into a single env var

}

/// Target name for verbose logs that should be filtered in quiet mode.
/// Use `tracing::info!(target: windmill_common::tracing_init::VERBOSE_TARGET, ...)` for logs that should be suppressed in quiet mode.
pub const VERBOSE_TARGET: &str = "windmill_verbose";

/// Creates a Targets filter that optionally filters out verbose logs when quiet mode is enabled.
fn create_targets_filter(default_env_filter: LevelFilter) -> Targets {
let targets = Targets::new()
.with_target("windmill:job_log", tracing::level_filters::LevelFilter::OFF);

if *QUIET_MODE {
targets
.with_target(VERBOSE_TARGET, tracing::level_filters::LevelFilter::OFF)
.with_default(default_env_filter)
} else {
targets.with_default(default_env_filter)
}
}

pub const LOGS_SERVICE: &str = "logs/services/";
Expand Down Expand Up @@ -156,22 +175,14 @@ pub fn initialize_tracing(
.with_writer(std::io::stdout)
.flatten_event(true)
.with_filter(stdout_env_filter)
.with_filter(
Targets::new()
.with_target("windmill:job_log", tracing::level_filters::LevelFilter::OFF)
.with_default(default_env_filter),
);
.with_filter(create_targets_filter(default_env_filter));

// File layer with its own filter
let file_layer = json_layer()
.with_writer(log_file_writer)
.flatten_event(true)
.with_filter(file_env_filter)
.with_filter(
Targets::new()
.with_target("windmill:job_log", tracing::level_filters::LevelFilter::OFF)
.with_default(default_env_filter),
);
.with_filter(create_targets_filter(default_env_filter));

base_layer
.with(stdout_layer)
Expand All @@ -188,11 +199,7 @@ pub fn initialize_tracing(
.with_line_number(true)
.with_target(false)
.with_filter(stdout_env_filter)
.with_filter(
Targets::new()
.with_target("windmill:job_log", tracing::level_filters::LevelFilter::OFF)
.with_default(default_env_filter),
);
.with_filter(create_targets_filter(default_env_filter));

// File layer with its own filter
let file_layer = compact_layer()
Expand All @@ -202,11 +209,7 @@ pub fn initialize_tracing(
.with_line_number(true)
.with_target(false)
.with_filter(file_env_filter)
.with_filter(
Targets::new()
.with_target("windmill:job_log", tracing::level_filters::LevelFilter::OFF)
.with_default(default_env_filter),
);
.with_filter(create_targets_filter(default_env_filter));

base_layer
.with(stdout_layer)
Expand Down
16 changes: 12 additions & 4 deletions backend/windmill-worker/src/handle_child.rs
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,8 @@ use crate::job_logger_oss::process_streaming_log_lines;
use crate::worker_utils::{ping_job_status, update_worker_ping_from_job};
use crate::{MAX_RESULT_SIZE, MAX_WAIT_FOR_SIGINT, MAX_WAIT_FOR_SIGTERM};

use windmill_common::tracing_init::{QUIET_MODE, VERBOSE_TARGET};

lazy_static::lazy_static! {
pub static ref SLOW_LOGS: bool = std::env::var("SLOW_LOGS").ok().is_some_and(|x| x == "1" || x == "true");
pub static ref OTEL_JOB_LOGS: bool = std::env::var("OTEL_JOB_LOGS").ok().is_some_and(|x| x == "1" || x == "true");
Expand Down Expand Up @@ -702,9 +704,11 @@ where
tokio::select!(
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The comment mentions "update the last_ping column every 5 seconds (or 50 seconds in quiet mode)" but the quiet mode change only affects log frequency, not the ping interval. The ping frequency is still controlled by the update_job_row logic on line 733 and is unchanged.

Suggested change
tokio::select!(
// update the last_ping column every 5 seconds (or 50 seconds in quiet mode)

Consider updating to:

Suggested change
tokio::select!(
// Log memory snapshot and ping status (in quiet mode, logs emit 10x less frequently)

_ = rx.recv() => break,
_ = interval.tick() => {
// update the last_ping column every 5 seconds
// update the last_ping column every 5 seconds (or 50 seconds in quiet mode)
i+=1;
if i == 1 || i % 10 == 0 {
// In quiet mode, emit memory snapshot logs 10x less frequently
let memory_snapshot_interval = if *QUIET_MODE { 100 } else { 10 };
if i == 1 || i % memory_snapshot_interval == 0 {
let memory_usage = get_worker_memory_usage();
let wm_memory_usage = get_windmill_memory_usage();
tracing::info!("job {job_id} on {worker_name} in {w_id} worker memory snapshot {}kB/{}kB", memory_usage.unwrap_or_default()/1024, wm_memory_usage.unwrap_or_default()/1024);
Expand All @@ -719,7 +723,11 @@ where
if current_mem > *mem_peak {
*mem_peak = current_mem
}
tracing::info!("job {job_id} on {worker_name} in {w_id} still running. mem: {current_mem}kB, peak mem: {mem_peak}kB");
// In quiet mode, emit "still running" logs 10x less frequently
let still_running_interval = if *QUIET_MODE { 10 } else { 1 };
if i % still_running_interval == 0 {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note: With still_running_interval = 10, the condition i % 10 == 0 means the first "still running" log will appear at tick 10 (5 seconds) in quiet mode, whereas normally it appears at every tick.

At tick 1: 1 % 10 = 1 ≠ 0 → no log
At tick 10: 10 % 10 = 0 → log

This is likely the intended behavior, just confirming it's not accidental that the first few ticks are skipped.

tracing::info!("job {job_id} on {worker_name} in {w_id} still running. mem: {current_mem}kB, peak mem: {mem_peak}kB");
}


let update_job_row = i == 2 || (!*SLOW_LOGS && (i < 20 || (i < 120 && i % 5 == 0) || i % 10 == 0)) || i % 20 == 0;
Expand Down Expand Up @@ -778,7 +786,7 @@ where
},
);
}
tracing::info!("job {job_id} finished");
tracing::info!(target: VERBOSE_TARGET, "job {job_id} finished");

UpdateJobPollingExit::Done(canceled_by_ref.clone())
}
Expand Down
9 changes: 7 additions & 2 deletions backend/windmill-worker/src/worker.rs
Original file line number Diff line number Diff line change
Expand Up @@ -77,6 +77,7 @@ use windmill_common::{
flows::FlowNodeId,
jobs::JobKind,
scripts::{get_full_hub_script_by_path, ScriptHash, ScriptLang},
tracing_init::{QUIET_MODE, VERBOSE_TARGET},
utils::StripPath,
worker::{CLOUD_HOSTED, NO_LOGS, WORKER_CONFIG, WORKER_GROUP},
DB, IS_READY,
Expand Down Expand Up @@ -1027,7 +1028,7 @@ pub fn start_interactive_worker_shell(

match pulled_job {
Ok(Some(job)) => {
tracing::debug!(worker = %worker_name, hostname = %hostname, "started handling of job {}", job.id);
tracing::debug!(target: VERBOSE_TARGET, worker = %worker_name, hostname = %hostname, "started handling of job {}", job.id);
let job_dir = create_job_dir(&worker_dir, job.id).await;
#[cfg(feature = "benchmark")]
let mut bench = windmill_common::bench::BenchmarkIter::new();
Expand Down Expand Up @@ -1901,7 +1902,7 @@ pub async fn run_worker(
last_executed_job = None;
jobs_executed += 1;

tracing::debug!(worker = %worker_name, hostname = %hostname, "started handling of job {}", job.id);
tracing::debug!(target: VERBOSE_TARGET, worker = %worker_name, hostname = %hostname, "started handling of job {}", job.id);

if matches!(
job.kind,
Expand Down Expand Up @@ -2835,6 +2836,10 @@ pub async fn handle_queued_job(
logs.push_str("Logs are 10x less frequent for this worker\n");
}

if *QUIET_MODE {
logs.push_str("Quiet mode enabled: verbose service logs are suppressed\n");
}

#[cfg(not(feature = "enterprise"))]
if let Connection::Sql(db) = conn {
if (job.concurrent_limit.is_some() ||
Expand Down
Loading