use super::LoggerManager;
use super::recovery::SinkControlMessage;
use crate::InklogConfig;
use crate::Metrics;
use crate::support::io::LogSink;
use crate::{InklogError, LogRecord};
use chrono::Utc;
use crossbeam_channel::{Receiver, Sender, bounded};
use std::sync::atomic::{AtomicUsize, Ordering};
use std::sync::{Arc, Mutex};
use std::thread;
use std::time::{Duration, Instant};
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
type DbSinkFactory = Box<
dyn Fn(
Arc<dyn crate::integrations::Database>,
Arc<Metrics>,
) -> Result<Box<dyn LogSink>, InklogError>
+ Send
+ Sync,
>;
pub(crate) struct WorkerParams {
pub(crate) config: InklogConfig,
pub(crate) receiver: Receiver<Arc<LogRecord>>,
pub(crate) console_receiver: Receiver<Arc<LogRecord>>,
pub(crate) control_rx: Receiver<SinkControlMessage>,
pub(crate) control_tx: Sender<SinkControlMessage>,
pub(crate) metrics: Arc<Metrics>,
pub(crate) console_sink: Arc<dyn LogSink>,
pub(crate) error_sink: Arc<Mutex<Option<Arc<dyn LogSink>>>>,
pub(crate) effective_capacity: Arc<AtomicUsize>,
pub(crate) file_sink_factory:
Box<dyn Fn() -> Result<Box<dyn LogSink>, InklogError> + Send + Sync>,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
pub(crate) db_sink_factory: DbSinkFactory,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
pub(crate) database: Option<Arc<dyn crate::integrations::Database>>,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
pub(crate) db_receiver: Option<Receiver<Arc<LogRecord>>>,
pub(crate) custom_sinks: Vec<CustomSinkEntry>,
}
pub(crate) struct CustomSinkEntry {
pub(crate) name: String,
pub(crate) sink: Arc<dyn LogSink>,
pub(crate) receiver: Receiver<Arc<LogRecord>>,
}
pub(crate) type WorkerStartResult =
Result<(Vec<tokio::task::JoinHandle<()>>, Vec<Sender<()>>), InklogError>;
const CUSTOM_SINK_WRITE_ATTEMPTS: u32 = 3;
pub(crate) fn run_custom_sink_worker(
runtime_handle: &tokio::runtime::Handle,
metrics: &Metrics,
console_sink: &Arc<dyn LogSink>,
entry: &CustomSinkEntry,
receiver: &Receiver<Arc<LogRecord>>,
shutdown: &Receiver<()>,
) {
loop {
if shutdown.try_recv().is_ok() {
let deadline = Instant::now() + Duration::from_secs(5);
while let Ok(record) = receiver.try_recv() {
metrics.record_latency(record_age(&record));
let _ = runtime_handle.block_on(async { entry.sink.write(&record).await });
if Instant::now() > deadline {
break;
}
}
let _ = runtime_handle.block_on(async { entry.sink.flush().await });
let _ = runtime_handle.block_on(async { entry.sink.shutdown().await });
break;
}
match receiver.recv_timeout(Duration::from_millis(100)) {
Ok(record) => {
metrics.record_latency(record_age(&record));
let mut written = false;
for attempt in 1..=CUSTOM_SINK_WRITE_ATTEMPTS {
match runtime_handle.block_on(async { entry.sink.write(&record).await }) {
Ok(_) => {
metrics.inc_logs_written();
metrics.update_sink_health(&entry.name, true, None);
written = true;
break;
}
Err(e) => {
tracing::error!(
error = %e,
attempt,
"custom sink '{}' write failed",
entry.name
);
if attempt == CUSTOM_SINK_WRITE_ATTEMPTS {
metrics.inc_sink_error();
metrics.update_sink_health(&entry.name, false, Some(e.to_string()));
let _ = runtime_handle
.block_on(async { console_sink.write(&record).await });
} else {
thread::sleep(Duration::from_millis(10 * attempt as u64));
}
}
}
}
let _ = written;
}
Err(crossbeam_channel::RecvTimeoutError::Timeout) => {
let _ = runtime_handle.block_on(async { entry.sink.flush().await });
}
Err(crossbeam_channel::RecvTimeoutError::Disconnected) => break,
}
}
}
pub(crate) fn should_auto_recover(
consecutive_failures: u32,
last_failure_time: Option<Instant>,
) -> bool {
consecutive_failures > 5
&& last_failure_time
.map(|t| t.elapsed() > Duration::from_secs(60))
.unwrap_or(false)
}
pub(crate) fn should_attempt_recovery(last_attempt: Option<&Instant>, cooldown: Duration) -> bool {
match last_attempt {
None => true,
Some(inst) => inst.elapsed() > cooldown,
}
}
pub(crate) enum ControlAction {
Recover,
Ignore,
}
pub(crate) fn classify_control_message(
msg: &SinkControlMessage,
target_sink: &str,
) -> ControlAction {
match msg {
SinkControlMessage::RecoverSink(name) if name == target_sink => ControlAction::Recover,
_ => ControlAction::Ignore,
}
}
#[allow(clippy::too_many_arguments)]
pub(crate) fn update_adaptive_capacity(
current_eff: usize,
channel_len: usize,
min_capacity: usize,
max_capacity: usize,
expand_threshold_percent: u8,
shrink_threshold_percent: u8,
shrink_wait: Duration,
low_usage_since: &mut Option<Instant>,
) -> usize {
let usage = if current_eff > 0 {
channel_len as f64 / current_eff as f64
} else {
0.0
};
let usage_percent = (usage * 100.0).round() as u8;
if usage_percent >= expand_threshold_percent && current_eff < max_capacity {
let grow_to = (current_eff + current_eff / 2).min(max_capacity);
*low_usage_since = None;
grow_to
} else if usage_percent <= shrink_threshold_percent && current_eff > min_capacity {
match low_usage_since {
None => {
*low_usage_since = Some(Instant::now());
current_eff
}
Some(inst) => {
if inst.elapsed() >= shrink_wait {
let shrink_to = (current_eff.saturating_mul(70) / 100).max(min_capacity);
*low_usage_since = None;
shrink_to
} else {
current_eff
}
}
}
} else {
*low_usage_since = None;
current_eff
}
}
const FACTORY_RETRY_INITIAL_BACKOFF: Duration = Duration::from_secs(1);
const FACTORY_RETRY_MAX_BACKOFF: Duration = Duration::from_secs(30);
#[cfg(test)]
static FACTORY_RETRY_INITIAL_BACKOFF_MS: std::sync::atomic::AtomicU64 =
std::sync::atomic::AtomicU64::new(0);
fn factory_retry_initial_backoff() -> Duration {
#[cfg(test)]
{
let ms = FACTORY_RETRY_INITIAL_BACKOFF_MS.load(Ordering::Relaxed);
if ms > 0 {
return Duration::from_millis(ms);
}
}
FACTORY_RETRY_INITIAL_BACKOFF
}
const WRITE_MAX_ATTEMPTS: u32 = 3;
struct SinkWorkerDescriptor {
name: &'static str,
label: &'static str,
error_target: &'static str,
recovery_received_key: &'static str,
recovered_key: &'static str,
recovery_failed_key: &'static str,
auto_recovery_key: &'static str,
auto_recovery_ok_key: &'static str,
}
const FILE_SINK_WORKER: SinkWorkerDescriptor = SinkWorkerDescriptor {
name: "file",
label: "File",
error_target: "inklog::file_sink",
recovery_received_key: "sink-file_recovery_received",
recovered_key: "sink-file_recovered",
recovery_failed_key: "sink-file_recovery_failed",
auto_recovery_key: "sink-file_auto_recovery",
auto_recovery_ok_key: "sink-file_auto_recovery_ok",
};
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
const DB_SINK_WORKER: SinkWorkerDescriptor = SinkWorkerDescriptor {
name: "database",
label: "Database",
error_target: "inklog::database_sink",
recovery_received_key: "sink-db_recovery_received",
recovered_key: "sink-db_recovered",
recovery_failed_key: "sink-db_recovery_failed",
auto_recovery_key: "sink-db_auto_recovery",
auto_recovery_ok_key: "sink-db_auto_recovery_ok",
};
type SinkFactory<'a> = &'a mut dyn FnMut() -> Result<Box<dyn LogSink>, InklogError>;
#[derive(Default)]
struct FailureState {
consecutive_failures: u32,
last_failure_time: Option<Instant>,
}
struct SinkWorkerState {
sink: Option<Box<dyn LogSink>>,
failures: FailureState,
factory_backoff: Duration,
last_factory_attempt: Instant,
}
struct SinkWorker<'a> {
desc: &'static SinkWorkerDescriptor,
runtime_handle: &'a tokio::runtime::Handle,
metrics: &'a Metrics,
console_sink: &'a Arc<dyn LogSink>,
error_sink: &'a Arc<Mutex<Option<Arc<dyn LogSink>>>>,
}
fn record_age(record: &LogRecord) -> Duration {
Utc::now()
.signed_duration_since(record.timestamp)
.to_std()
.unwrap_or(Duration::ZERO)
}
impl SinkWorker<'_> {
fn create_initial_state(&self, create_sink: SinkFactory<'_>) -> SinkWorkerState {
let sink = match create_sink() {
Ok(sink) => Some(sink),
Err(e) => {
tracing::error!(
error = %e,
"{} sink factory failed on startup; entering degraded retry mode (exponential backoff: 1s doubling up to 30s, retrying indefinitely); records arriving during retry are forwarded to the error sink and counted as failed",
self.desc.label
);
self.metrics
.update_sink_health(self.desc.name, false, Some(e.to_string()));
None
}
};
SinkWorkerState {
sink,
failures: FailureState::default(),
factory_backoff: factory_retry_initial_backoff(),
last_factory_attempt: Instant::now(),
}
}
fn handle_record(
&self,
state: &mut SinkWorkerState,
record: &Arc<LogRecord>,
create_sink: SinkFactory<'_>,
) {
self.metrics.record_latency(record_age(record));
let Some(sink) = state.sink.as_mut() else {
self.handle_sink_unavailable(record);
return;
};
let write_succeeded = self.write_with_retry(sink, record, &mut state.failures);
if !write_succeeded {
self.maybe_auto_recover(&mut state.failures, sink, create_sink);
}
}
fn handle_sink_unavailable(&self, record: &Arc<LogRecord>) {
self.metrics.inc_sink_error();
self.metrics.inc_logs_dropped();
self.metrics.update_sink_health(
self.desc.name,
false,
Some("sink unavailable: factory keeps failing".to_string()),
);
let error_sink_handle = self.error_sink.lock().ok().and_then(|guard| guard.clone());
if let Some(error_sink) = error_sink_handle {
let _ = self
.runtime_handle
.block_on(async { error_sink.write(record).await });
}
}
fn write_with_retry(
&self,
sink: &mut Box<dyn LogSink>,
record: &Arc<LogRecord>,
failures: &mut FailureState,
) -> bool {
let mut attempts = 0;
while attempts < WRITE_MAX_ATTEMPTS {
match self
.runtime_handle
.block_on(async { sink.write(record).await })
{
Ok(_) => {
self.metrics.inc_logs_written();
self.metrics.update_sink_health(self.desc.name, true, None);
failures.consecutive_failures = 0;
failures.last_failure_time = None;
return true;
}
Err(e) => {
attempts += 1;
failures.consecutive_failures += 1;
failures.last_failure_time = Some(Instant::now());
self.write_error_log(&e);
if attempts == WRITE_MAX_ATTEMPTS {
self.metrics.inc_sink_error();
self.metrics
.update_sink_health(self.desc.name, false, Some(e.to_string()));
self.fallback_to_console(record);
} else {
thread::sleep(Duration::from_millis(10 * attempts as u64));
}
}
}
}
false
}
fn write_error_log(&self, error: &InklogError) {
let error_sink_handle = self.error_sink.lock().ok().and_then(|guard| guard.clone());
let Some(error_sink) = error_sink_handle else {
return;
};
let error_record = LogRecord {
timestamp: Utc::now(),
level: "ERROR".to_string(),
target: self.desc.error_target.to_string(),
message: format!("{} sink error: {}", self.desc.label, error),
fields: Default::default(),
file: None,
line: None,
thread_id: thread::current().name().unwrap_or("unknown").to_string(),
trace_id: None,
span_id: None,
};
let _ = self
.runtime_handle
.block_on(async { error_sink.write(&error_record).await });
}
fn fallback_to_console(&self, record: &Arc<LogRecord>) {
let _ = self
.runtime_handle
.block_on(async { self.console_sink.write(record).await });
}
fn maybe_auto_recover(
&self,
failures: &mut FailureState,
sink: &mut Box<dyn LogSink>,
create_sink: SinkFactory<'_>,
) {
if !should_auto_recover(failures.consecutive_failures, failures.last_failure_time) {
return;
}
tracing::warn!("{}", crate::i18n::tr(self.desc.auto_recovery_key));
if let Ok(new_sink) = create_sink() {
*sink = new_sink;
failures.consecutive_failures = 0;
failures.last_failure_time = None;
self.metrics.update_sink_health(self.desc.name, true, None);
tracing::info!("{}", crate::i18n::tr(self.desc.auto_recovery_ok_key));
}
}
fn handle_control_message(
&self,
state: &mut SinkWorkerState,
msg: &SinkControlMessage,
create_sink: SinkFactory<'_>,
) {
match classify_control_message(msg, self.desc.name) {
ControlAction::Recover => {
tracing::info!("{}", crate::i18n::tr(self.desc.recovery_received_key));
if let Ok(new_sink) = create_sink() {
state.sink = Some(new_sink);
state.factory_backoff = factory_retry_initial_backoff();
state.failures.consecutive_failures = 0;
state.failures.last_failure_time = None;
self.metrics.update_sink_health(self.desc.name, true, None);
tracing::info!("{}", crate::i18n::tr(self.desc.recovered_key));
} else {
tracing::error!("{}", crate::i18n::tr(self.desc.recovery_failed_key));
}
}
ControlAction::Ignore => {}
}
}
fn retry_factory_if_due(&self, state: &mut SinkWorkerState, create_sink: SinkFactory<'_>) {
if state.sink.is_some() || state.last_factory_attempt.elapsed() < state.factory_backoff {
return;
}
match create_sink() {
Ok(new_sink) => {
state.sink = Some(new_sink);
state.factory_backoff = factory_retry_initial_backoff();
self.metrics.update_sink_health(self.desc.name, true, None);
tracing::info!(
"{} sink factory succeeded after retry; worker resumed normal writes",
self.desc.label
);
}
Err(e) => {
tracing::error!(
error = %e,
next_retry_in_ms = state.factory_backoff.as_millis() as u64,
"{} sink factory retry failed; keeping the worker alive and retrying with exponential backoff",
self.desc.label
);
state.factory_backoff = (state.factory_backoff * 2).min(FACTORY_RETRY_MAX_BACKOFF);
}
}
state.last_factory_attempt = Instant::now();
}
fn drain(
&self,
state: &mut SinkWorkerState,
receiver: &Receiver<Arc<LogRecord>>,
timeout: Duration,
create_sink: SinkFactory<'_>,
) {
let deadline = Instant::now() + timeout;
while let Ok(record) = receiver.try_recv() {
self.handle_record(state, &record, create_sink);
if Instant::now() > deadline {
break;
}
}
if let Some(sink) = state.sink.as_ref() {
let _ = self
.runtime_handle
.block_on(async { sink.shutdown().await });
}
}
fn flush_idle(&self, state: &SinkWorkerState) {
if let Some(sink) = state.sink.as_ref() {
let _ = self.runtime_handle.block_on(async { sink.flush().await });
}
}
}
impl LoggerManager {
pub(crate) fn start_workers(params: WorkerParams) -> WorkerStartResult {
let runtime_handle = tokio::runtime::Handle::current();
let WorkerParams {
config,
receiver,
console_receiver,
control_rx,
control_tx,
metrics,
console_sink,
error_sink,
effective_capacity,
file_sink_factory,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
db_sink_factory,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
database,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
db_receiver,
custom_sinks,
} = params;
let file_config = config.file_sink.clone();
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let db_config = config.database_sink.clone();
let (shutdown_tx_console, shutdown_console) = bounded(1);
let metrics_console = metrics.clone();
let console_sink_console = console_sink.clone();
let handle_console = {
let runtime_handle = runtime_handle.clone();
tokio::task::spawn_blocking(move || {
metrics_console.active_workers.inc();
loop {
if shutdown_console.try_recv().is_ok() {
let deadline = Instant::now() + Duration::from_secs(5);
while let Ok(record) = console_receiver.try_recv() {
metrics_console.record_latency(record_age(&record));
if runtime_handle
.block_on(async { console_sink_console.write(&record).await })
.is_err()
{
metrics_console.inc_sink_error();
}
if Instant::now() > deadline {
break;
}
}
break;
}
match console_receiver.recv_timeout(Duration::from_millis(100)) {
Ok(record) => {
metrics_console.record_latency(record_age(&record));
match runtime_handle
.block_on(async { console_sink_console.write(&record).await })
{
Ok(_) => {
metrics_console.inc_logs_written();
metrics_console.update_sink_health("console", true, None);
}
Err(_) => {
metrics_console.inc_sink_error();
metrics_console.update_sink_health(
"console",
false,
Some("Write error".to_string()),
);
}
}
}
Err(crossbeam_channel::RecvTimeoutError::Timeout) => {
}
Err(crossbeam_channel::RecvTimeoutError::Disconnected) => {
break;
}
}
}
metrics_console.active_workers.dec();
})
};
let rx_file = receiver.clone();
let (shutdown_tx_file, shutdown_file) = bounded(1);
let metrics_file = metrics.clone();
let console_sink_file = console_sink.clone();
let error_sink_file = error_sink.clone();
let control_rx_file = control_rx.clone();
let handle_file = {
let runtime_handle = runtime_handle.clone();
tokio::task::spawn_blocking(move || {
metrics_file.active_workers.inc();
if let Some(cfg) = file_config
&& cfg.enabled
{
let worker = SinkWorker {
desc: &FILE_SINK_WORKER,
runtime_handle: &runtime_handle,
metrics: &metrics_file,
console_sink: &console_sink_file,
error_sink: &error_sink_file,
};
let mut create_sink = || file_sink_factory();
let mut state = worker.create_initial_state(&mut create_sink);
loop {
if shutdown_file.try_recv().is_ok() {
worker.drain(
&mut state,
&rx_file,
Duration::from_secs(30),
&mut create_sink,
);
break;
}
if let Ok(control_msg) = control_rx_file.try_recv() {
worker.handle_control_message(
&mut state,
&control_msg,
&mut create_sink,
);
}
worker.retry_factory_if_due(&mut state, &mut create_sink);
match rx_file.recv_timeout(Duration::from_millis(100)) {
Ok(record) => {
worker.handle_record(&mut state, &record, &mut create_sink);
}
Err(crossbeam_channel::RecvTimeoutError::Timeout) => {
worker.flush_idle(&state);
}
Err(crossbeam_channel::RecvTimeoutError::Disconnected) => break,
}
}
}
metrics_file.active_workers.dec();
})
};
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let (shutdown_tx_db, shutdown_db) = bounded(1);
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let metrics_db = metrics.clone();
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let console_sink_db = console_sink.clone();
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let error_sink_db = error_sink.clone();
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let control_rx_db = control_rx.clone();
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let handle_db = {
let runtime_handle = runtime_handle.clone();
tokio::task::spawn_blocking(move || {
metrics_db.active_workers.inc();
if let Some(cfg) = db_config
&& cfg.enabled
&& let Some(ref db) = database
&& let Some(rx_db) = db_receiver
{
let worker = SinkWorker {
desc: &DB_SINK_WORKER,
runtime_handle: &runtime_handle,
metrics: &metrics_db,
console_sink: &console_sink_db,
error_sink: &error_sink_db,
};
let mut create_sink = || db_sink_factory(db.clone(), metrics_db.clone());
let mut state = worker.create_initial_state(&mut create_sink);
loop {
if shutdown_db.try_recv().is_ok() {
worker.drain(
&mut state,
&rx_db,
Duration::from_secs(30),
&mut create_sink,
);
break;
}
if let Ok(control_msg) = control_rx_db.try_recv() {
worker.handle_control_message(
&mut state,
&control_msg,
&mut create_sink,
);
}
worker.retry_factory_if_due(&mut state, &mut create_sink);
match rx_db.recv_timeout(Duration::from_millis(100)) {
Ok(record) => {
worker.handle_record(&mut state, &record, &mut create_sink);
}
Err(crossbeam_channel::RecvTimeoutError::Timeout) => {
worker.flush_idle(&state);
}
Err(crossbeam_channel::RecvTimeoutError::Disconnected) => break,
}
}
}
metrics_db.active_workers.dec();
})
};
let mut custom_handles = Vec::with_capacity(custom_sinks.len());
let mut custom_shutdown_txs = Vec::with_capacity(custom_sinks.len());
for entry in custom_sinks {
let (shutdown_tx, shutdown_rx) = bounded(1);
let metrics_custom = metrics.clone();
let console_sink_custom = console_sink.clone();
let runtime_handle_custom = runtime_handle.clone();
custom_handles.push(tokio::task::spawn_blocking(move || {
metrics_custom.active_workers.inc();
run_custom_sink_worker(
&runtime_handle_custom,
&metrics_custom,
&console_sink_custom,
&entry,
&entry.receiver,
&shutdown_rx,
);
metrics_custom.active_workers.dec();
}));
custom_shutdown_txs.push(shutdown_tx);
}
let (shutdown_tx_health, shutdown_health) = bounded(1);
let metrics_health = metrics.clone();
let effective_capacity_health = effective_capacity.clone();
let handle_health = tokio::task::spawn_blocking(move || {
let mut last_recovery_attempt = std::collections::HashMap::<String, Instant>::new();
let mut low_usage_since: Option<Instant> = None;
let check_interval = Duration::from_secs(1);
loop {
match shutdown_health.recv_timeout(check_interval) {
Ok(_) => break,
Err(crossbeam_channel::RecvTimeoutError::Timeout) => {}
Err(crossbeam_channel::RecvTimeoutError::Disconnected) => break,
}
let current_eff = effective_capacity_health.load(Ordering::Relaxed);
let channel_len_now = receiver.len();
let status = metrics_health.get_status(channel_len_now, current_eff);
if config.performance.channel_strategy == crate::ChannelStrategy::Adaptive {
let new_cap = update_adaptive_capacity(
current_eff,
channel_len_now,
config.performance.min_capacity,
config.performance.max_capacity,
config.performance.expand_threshold_percent,
config.performance.shrink_threshold_percent,
Duration::from_secs(config.performance.shrink_wait_seconds),
&mut low_usage_since,
);
effective_capacity_health.store(new_cap, Ordering::Relaxed);
}
for (name, sink_status) in status.sinks {
if !sink_status.status.is_operational() {
let mut args = fluent_bundle::FluentArgs::new();
args.set("name", name.clone());
args.set("error", format!("{:?}", sink_status.last_error));
tracing::warn!("{}", crate::i18n::tr_args("sink-health_unhealthy", args));
let should_recover = should_attempt_recovery(
last_recovery_attempt.get(&name),
Duration::from_secs(30),
);
if should_recover && sink_status.consecutive_failures > 3 {
let mut args = fluent_bundle::FluentArgs::new();
args.set("name", name.clone());
tracing::warn!(
"{}",
crate::i18n::tr_args("sink-health_attempting_recovery", args)
);
if let Err(e) =
control_tx.send(SinkControlMessage::RecoverSink(name.clone()))
{
let mut args = fluent_bundle::FluentArgs::new();
args.set("name", name.clone());
args.set("err", e.to_string());
tracing::error!(
"{}",
crate::i18n::tr_args("sink-health_send_failed", args)
);
} else {
last_recovery_attempt.insert(name.clone(), Instant::now());
tracing::info!(
"Health Check: Recovery command sent for sink '{}'",
name
);
}
}
if sink_status.consecutive_failures > 10 {
tracing::error!(
"CRITICAL: Sink '{}' has high error count ({})",
name,
sink_status.consecutive_failures
);
}
} else {
last_recovery_attempt.remove(&name);
}
}
}
});
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let mut handles = vec![handle_console, handle_file, handle_db, handle_health];
#[cfg(not(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
)))]
let mut handles = vec![handle_console, handle_file, handle_health];
handles.extend(custom_handles);
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
let mut shutdown_txs = vec![
shutdown_tx_console,
shutdown_tx_file,
shutdown_tx_db,
shutdown_tx_health,
];
#[cfg(not(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
)))]
let mut shutdown_txs = vec![shutdown_tx_console, shutdown_tx_file, shutdown_tx_health];
shutdown_txs.extend(custom_shutdown_txs);
Ok((handles, shutdown_txs))
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn test_should_auto_recover_low_failures() {
assert!(!should_auto_recover(
5,
Some(Instant::now() - Duration::from_secs(120))
));
assert!(!should_auto_recover(
0,
Some(Instant::now() - Duration::from_secs(120))
));
}
#[test]
fn test_should_auto_recover_high_failures_no_time() {
assert!(!should_auto_recover(10, None));
}
#[test]
fn test_should_auto_recover_high_failures_recent() {
assert!(!should_auto_recover(
10,
Some(Instant::now() - Duration::from_secs(30))
));
}
#[test]
fn test_should_auto_recover_high_failures_old() {
assert!(should_auto_recover(
6,
Some(Instant::now() - Duration::from_secs(61))
));
assert!(should_auto_recover(
100,
Some(Instant::now() - Duration::from_secs(300))
));
}
#[test]
fn test_should_attempt_recovery_never() {
assert!(should_attempt_recovery(None, Duration::from_secs(30)));
}
#[test]
fn test_should_attempt_recovery_within_cooldown() {
let recent = Instant::now() - Duration::from_secs(10);
assert!(!should_attempt_recovery(
Some(&recent),
Duration::from_secs(30)
));
}
#[test]
fn test_should_attempt_recovery_after_cooldown() {
let old = Instant::now() - Duration::from_secs(60);
assert!(should_attempt_recovery(Some(&old), Duration::from_secs(30)));
}
#[test]
fn test_classify_control_recover_matching() {
let msg = SinkControlMessage::RecoverSink("file".to_string());
assert!(matches!(
classify_control_message(&msg, "file"),
ControlAction::Recover
));
}
#[test]
fn test_classify_control_recover_non_matching() {
let msg = SinkControlMessage::RecoverSink("database".to_string());
assert!(matches!(
classify_control_message(&msg, "file"),
ControlAction::Ignore
));
}
#[test]
fn test_update_adaptive_capacity_expand() {
let mut low_usage_since: Option<Instant> = None;
let new_cap = update_adaptive_capacity(
100,
80,
50,
200,
70,
30,
Duration::from_secs(60),
&mut low_usage_since,
);
assert_eq!(new_cap, 150); assert!(low_usage_since.is_none());
}
#[test]
fn test_update_adaptive_capacity_shrink_after_wait() {
let mut low_usage_since = Some(Instant::now() - Duration::from_secs(120));
let new_cap = update_adaptive_capacity(
100,
10,
50,
200,
70,
30,
Duration::from_secs(60),
&mut low_usage_since,
);
assert_eq!(new_cap, 70); assert!(low_usage_since.is_none());
}
#[test]
fn test_update_adaptive_capacity_shrink_starts_timer() {
let mut low_usage_since: Option<Instant> = None;
let new_cap = update_adaptive_capacity(
100,
10,
50,
200,
70,
30,
Duration::from_secs(60),
&mut low_usage_since,
);
assert_eq!(new_cap, 100);
assert!(low_usage_since.is_some());
}
#[test]
fn test_update_adaptive_capacity_stable() {
let mut low_usage_since: Option<Instant> = None;
let new_cap = update_adaptive_capacity(
100,
50,
50,
200,
70,
30,
Duration::from_secs(60),
&mut low_usage_since,
);
assert_eq!(new_cap, 100);
}
#[test]
fn test_update_adaptive_capacity_respects_max() {
let mut low_usage_since: Option<Instant> = None;
let new_cap = update_adaptive_capacity(
200,
180,
50,
200,
70,
30,
Duration::from_secs(60),
&mut low_usage_since,
);
assert_eq!(new_cap, 200);
}
#[test]
fn test_update_adaptive_capacity_respects_min() {
let mut low_usage_since = Some(Instant::now() - Duration::from_secs(120));
let new_cap = update_adaptive_capacity(
50,
0,
50,
200,
70,
30,
Duration::from_secs(60),
&mut low_usage_since,
);
assert_eq!(new_cap, 50);
}
#[test]
fn test_console_worker_concurrent_writes_terminate_without_deadlock() {
let runtime = tokio::runtime::Builder::new_multi_thread()
.worker_threads(2)
.enable_all()
.build()
.expect("Failed to build test runtime");
let config = InklogConfig::default();
let (file_tx, file_rx) = bounded::<Arc<LogRecord>>(100);
let (console_tx, console_rx) = bounded::<Arc<LogRecord>>(2048);
let (control_tx, control_rx) = bounded(10);
let metrics = Arc::new(Metrics::new());
let effective_capacity = Arc::new(AtomicUsize::new(2048));
let console_sink = Arc::new(crate::support::io::ConsoleSink::new(
config.console_sink.clone().unwrap_or_default(),
crate::LogTemplate::new(&config.global.format),
)) as Arc<dyn LogSink>;
let error_sink: Arc<Mutex<Option<Arc<dyn LogSink>>>> = Arc::new(Mutex::new(None));
let params = WorkerParams {
config,
receiver: file_rx,
console_receiver: console_rx,
control_rx,
control_tx,
metrics: metrics.clone(),
console_sink,
error_sink,
effective_capacity,
file_sink_factory: Box::new(|| {
Err(InklogError::ConfigError("unused in test".to_string()))
}),
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
db_sink_factory: Box::new(|_db, _metrics| {
Err(InklogError::ConfigError("unused in test".to_string()))
}),
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
database: None,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
db_receiver: None,
custom_sinks: Vec::new(),
};
let (handles, shutdown_txs) = runtime
.block_on(async { LoggerManager::start_workers(params).expect("start workers") });
let _ = file_tx;
let producers: Vec<_> = (0..4)
.map(|t| {
let tx = console_tx.clone();
thread::spawn(move || {
for i in 0..100 {
let record = Arc::new(LogRecord {
timestamp: Utc::now(),
level: "INFO".to_string(),
target: format!("concurrent::{t}"),
message: format!("concurrent write {t}-{i}"),
fields: Default::default(),
file: None,
line: None,
thread_id: "test".to_string(),
trace_id: None,
span_id: None,
});
if tx.send(record).is_err() {
break;
}
}
})
})
.collect();
for producer in producers {
producer.join().expect("producer thread panicked");
}
drop(console_tx);
for tx in &shutdown_txs {
let _ = tx.send_timeout((), Duration::from_secs(2));
}
let deadline = Instant::now() + Duration::from_secs(15);
let mut all_finished = true;
for handle in handles {
while !handle.is_finished() {
if Instant::now() > deadline {
all_finished = false;
break;
}
thread::sleep(Duration::from_millis(10));
}
handle.abort();
}
assert!(all_finished, "workers must terminate without deadlock");
assert_eq!(metrics.sink_errors(), 0, "console writes must not fail");
}
#[test]
#[serial_test::serial]
fn test_file_worker_failing_factory_counts_failed_and_exits_on_sender_drop() {
FACTORY_RETRY_INITIAL_BACKOFF_MS.store(20, Ordering::Relaxed);
let runtime = tokio::runtime::Builder::new_multi_thread()
.worker_threads(2)
.enable_all()
.build()
.expect("Failed to build test runtime");
let config = InklogConfig {
file_sink: Some(crate::FileSinkConfig {
enabled: true,
..Default::default()
}),
..Default::default()
};
let (file_tx, file_rx) = bounded::<Arc<LogRecord>>(100);
let (_console_tx, console_rx) = bounded::<Arc<LogRecord>>(100);
let (control_tx, control_rx) = bounded(10);
let metrics = Arc::new(Metrics::new());
let effective_capacity = Arc::new(AtomicUsize::new(100));
let console_sink = Arc::new(crate::support::io::ConsoleSink::new(
config.console_sink.clone().unwrap_or_default(),
crate::LogTemplate::new(&config.global.format),
)) as Arc<dyn LogSink>;
let error_sink: Arc<Mutex<Option<Arc<dyn LogSink>>>> = Arc::new(Mutex::new(None));
let params = WorkerParams {
config,
receiver: file_rx,
console_receiver: console_rx,
control_rx,
control_tx,
metrics: metrics.clone(),
console_sink,
error_sink,
effective_capacity,
file_sink_factory: Box::new(|| {
Err(InklogError::ConfigError(
"factory always fails in this test".to_string(),
))
}),
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
db_sink_factory: Box::new(|_db, _metrics| {
Err(InklogError::ConfigError("unused in test".to_string()))
}),
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
database: None,
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
db_receiver: None,
custom_sinks: Vec::new(),
};
let (handles, shutdown_txs) = runtime
.block_on(async { LoggerManager::start_workers(params).expect("start workers") });
const N: u64 = 5;
for i in 0..N {
let record = Arc::new(LogRecord {
timestamp: Utc::now(),
level: "INFO".to_string(),
target: "degraded::factory".to_string(),
message: format!("degraded record {i}"),
fields: Default::default(),
file: None,
line: None,
thread_id: "test".to_string(),
trace_id: None,
span_id: None,
});
file_tx.send(record).expect("send record");
}
drop(file_tx);
let deadline = Instant::now() + Duration::from_secs(5);
while metrics.sink_errors() < N && Instant::now() < deadline {
thread::sleep(Duration::from_millis(20));
}
assert!(
metrics.sink_errors() >= N,
"records arriving while the factory fails must be counted as failed, got: {}",
metrics.sink_errors()
);
assert!(
metrics.logs_dropped() >= N,
"records arriving while the factory fails must be counted as dropped, got: {}",
metrics.logs_dropped()
);
let deadline = Instant::now() + Duration::from_secs(5);
while !handles[1].is_finished() && Instant::now() < deadline {
thread::sleep(Duration::from_millis(10));
}
assert!(
handles[1].is_finished(),
"file worker must exit after all record senders are dropped, even with a failing factory"
);
for tx in &shutdown_txs {
let _ = tx.send_timeout((), Duration::from_secs(2));
}
let deadline = Instant::now() + Duration::from_secs(15);
let mut all_finished = true;
for handle in handles {
while !handle.is_finished() {
if Instant::now() > deadline {
all_finished = false;
break;
}
thread::sleep(Duration::from_millis(10));
}
handle.abort();
}
assert!(
all_finished,
"workers must terminate after shutdown even in degraded retry mode"
);
FACTORY_RETRY_INITIAL_BACKOFF_MS.store(0, Ordering::Relaxed);
}
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
struct CapturingSink {
messages: Mutex<Vec<String>>,
}
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
#[async_trait::async_trait]
impl LogSink for CapturingSink {
async fn write(&self, record: &LogRecord) -> Result<(), InklogError> {
self.messages.lock().unwrap().push(record.message.clone());
Ok(())
}
async fn flush(&self) -> Result<(), InklogError> {
Ok(())
}
async fn shutdown(&self) -> Result<(), InklogError> {
Ok(())
}
}
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
struct FailingDbSink;
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
#[async_trait::async_trait]
impl LogSink for FailingDbSink {
async fn write(&self, _record: &LogRecord) -> Result<(), InklogError> {
Err(InklogError::DatabaseError {
message: "mock db write failure".to_string(),
source: None,
})
}
async fn flush(&self) -> Result<(), InklogError> {
Ok(())
}
async fn shutdown(&self) -> Result<(), InklogError> {
Ok(())
}
}
#[cfg(any(
feature = "sqlite",
feature = "postgres",
feature = "mysql",
feature = "duckdb"
))]
#[test]
fn test_db_worker_write_failure_writes_error_log_in_main_loop() {
let runtime = tokio::runtime::Builder::new_multi_thread()
.worker_threads(2)
.enable_all()
.build()
.expect("Failed to build test runtime");
let mut config = InklogConfig::default();
config.database_sink = Some(crate::domain::config::DatabaseSinkConfig {
enabled: true,
..Default::default()
});
let (_file_tx, file_rx) = bounded::<Arc<LogRecord>>(100);
let (_console_tx, console_rx) = bounded::<Arc<LogRecord>>(100);
let (db_tx, db_rx) = bounded::<Arc<LogRecord>>(100);
let (control_tx, control_rx) = bounded(10);
let metrics = Arc::new(Metrics::new());
let effective_capacity = Arc::new(AtomicUsize::new(100));
let console_sink = Arc::new(crate::support::io::ConsoleSink::new(
config.console_sink.clone().unwrap_or_default(),
crate::LogTemplate::new(&config.global.format),
)) as Arc<dyn LogSink>;
let captured = Arc::new(CapturingSink {
messages: Mutex::new(Vec::new()),
});
let error_sink: Arc<Mutex<Option<Arc<dyn LogSink>>>> =
Arc::new(Mutex::new(Some(captured.clone() as Arc<dyn LogSink>)));
let params = WorkerParams {
config,
receiver: file_rx,
console_receiver: console_rx,
control_rx,
control_tx,
metrics: metrics.clone(),
console_sink,
error_sink,
effective_capacity,
file_sink_factory: Box::new(|| {
Err(InklogError::ConfigError("unused in test".to_string()))
}),
db_sink_factory: Box::new(|_db, _metrics| {
Ok(Box::new(FailingDbSink) as Box<dyn LogSink>)
}),
database: Some(Arc::new(crate::integrations::MockDatabaseAdapter::new())
as Arc<dyn crate::integrations::Database>),
db_receiver: Some(db_rx),
custom_sinks: Vec::new(),
};
let (handles, shutdown_txs) = runtime
.block_on(async { LoggerManager::start_workers(params).expect("start workers") });
const N: u64 = 3;
for i in 0..N {
let record = Arc::new(LogRecord {
timestamp: Utc::now(),
level: "INFO".to_string(),
target: "db::write_failure".to_string(),
message: format!("db write failure record {i}"),
fields: Default::default(),
file: None,
line: None,
thread_id: "test".to_string(),
trace_id: None,
span_id: None,
});
db_tx.send(record).expect("send db record");
}
drop(db_tx);
let deadline = Instant::now() + Duration::from_secs(5);
while metrics.sink_errors() < N && Instant::now() < deadline {
thread::sleep(Duration::from_millis(20));
}
assert!(
metrics.sink_errors() >= N,
"db main-loop write failures must be counted as sink errors, got: {}",
metrics.sink_errors()
);
let error_messages = captured.messages.lock().unwrap();
assert!(
error_messages.len() >= N as usize,
"db main-loop failures must write error.log, got: {}",
error_messages.len()
);
assert!(
error_messages
.iter()
.all(|m| m.starts_with("Database sink error: ")),
"error.log records must come from the database sink failure path, got: {:?}",
*error_messages
);
drop(error_messages);
for tx in &shutdown_txs {
let _ = tx.send_timeout((), Duration::from_secs(2));
}
let deadline = Instant::now() + Duration::from_secs(15);
let mut all_finished = true;
for handle in handles {
while !handle.is_finished() {
if Instant::now() > deadline {
all_finished = false;
break;
}
thread::sleep(Duration::from_millis(10));
}
handle.abort();
}
assert!(all_finished, "workers must terminate after shutdown");
}
}
#[cfg(test)]
mod custom_sink_worker_tests {
use super::*;
use parking_lot::Mutex;
struct MemorySink {
records: Mutex<Vec<String>>,
fail_times: AtomicUsize,
}
impl MemorySink {
fn new(fail_times: usize) -> Self {
Self {
records: Mutex::new(Vec::new()),
fail_times: AtomicUsize::new(fail_times),
}
}
}
#[async_trait::async_trait]
impl LogSink for MemorySink {
async fn write(&self, record: &LogRecord) -> Result<(), InklogError> {
if self.fail_times.load(Ordering::SeqCst) > 0 {
self.fail_times.fetch_sub(1, Ordering::SeqCst);
return Err(InklogError::ConfigError("transient failure".to_string()));
}
self.records.lock().push(record.message.clone());
Ok(())
}
async fn flush(&self) -> Result<(), InklogError> {
Ok(())
}
async fn shutdown(&self) -> Result<(), InklogError> {
Ok(())
}
}
#[test]
fn test_custom_sink_worker_consumes_records_and_drains_on_shutdown() {
let runtime = tokio::runtime::Builder::new_multi_thread()
.worker_threads(2)
.enable_all()
.build()
.unwrap();
let sink = Arc::new(MemorySink::new(0));
let (tx, rx) = bounded::<Arc<LogRecord>>(100);
let entry = CustomSinkEntry {
name: "custom-0".to_string(),
sink: sink.clone() as Arc<dyn LogSink>,
receiver: rx,
};
let (_shutdown_tx, shutdown_rx) = bounded(1);
let metrics = Arc::new(Metrics::new());
let console_sink = Arc::new(crate::support::io::ConsoleSink::new(
Default::default(),
crate::LogTemplate::new("{timestamp} [{level}] {target} - {message}"),
)) as Arc<dyn LogSink>;
let handle = {
let metrics = metrics.clone();
let console = console_sink.clone();
let runtime_handle = runtime.handle().clone();
thread::spawn(move || {
run_custom_sink_worker(
&runtime_handle,
&metrics,
&console,
&entry,
&entry.receiver,
&shutdown_rx,
);
})
};
for i in 0..3 {
tx.send(Arc::new(LogRecord {
timestamp: Utc::now(),
level: "INFO".to_string(),
target: "custom::sink".to_string(),
message: format!("custom record {i}"),
fields: Default::default(),
file: None,
line: None,
thread_id: "test".to_string(),
trace_id: None,
span_id: None,
}))
.unwrap();
}
let deadline = Instant::now() + Duration::from_secs(5);
while sink.records.lock().len() < 3 && Instant::now() < deadline {
thread::sleep(Duration::from_millis(10));
}
assert_eq!(sink.records.lock().len(), 3, "all records must be written");
assert!(metrics.logs_written() >= 3, "writes must be counted");
drop(tx);
drop(_shutdown_tx);
handle.join().expect("worker must exit cleanly");
}
#[test]
fn test_custom_sink_worker_retries_and_falls_back_to_console() {
let runtime = tokio::runtime::Builder::new_multi_thread()
.worker_threads(2)
.enable_all()
.build()
.unwrap();
let sink = Arc::new(MemorySink::new(3));
let (tx, rx) = bounded::<Arc<LogRecord>>(10);
let entry = CustomSinkEntry {
name: "custom-fail".to_string(),
sink: sink.clone() as Arc<dyn LogSink>,
receiver: rx,
};
let (_shutdown_tx, shutdown_rx) = bounded::<()>(1);
let metrics = Arc::new(Metrics::new());
let console_sink = Arc::new(crate::support::io::ConsoleSink::new(
Default::default(),
crate::LogTemplate::new("t"),
)) as Arc<dyn LogSink>;
{
let metrics = metrics.clone();
let console = console_sink.clone();
let runtime_handle = runtime.handle().clone();
thread::spawn(move || {
run_custom_sink_worker(
&runtime_handle,
&metrics,
&console,
&entry,
&entry.receiver,
&shutdown_rx,
);
});
}
tx.send(Arc::new(LogRecord {
timestamp: Utc::now(),
level: "INFO".to_string(),
target: "custom::fail".to_string(),
message: "doomed record".to_string(),
fields: Default::default(),
file: None,
line: None,
thread_id: "test".to_string(),
trace_id: None,
span_id: None,
}))
.unwrap();
let deadline = Instant::now() + Duration::from_secs(5);
while metrics.sink_errors() < 1 && Instant::now() < deadline {
thread::sleep(Duration::from_millis(10));
}
assert!(
metrics.sink_errors() >= 1,
"exhausted retries must count a sink error"
);
assert_eq!(
sink.records.lock().len(),
0,
"record must not be written after all attempts failed"
);
drop(tx);
}
}