v0.1.2-pre.005
This commit is contained in:
33
crates/ksp-logging-lib/README.md
Normal file
33
crates/ksp-logging-lib/README.md
Normal file
@@ -0,0 +1,33 @@
|
||||
<!-- file: crates/ksp-logging-lib/README.md -->
|
||||
<!-- version: 1 -->
|
||||
|
||||
# ksp-logging-lib
|
||||
|
||||
`ksp-logging-lib` est la façade commune de logging/tracing runtime de Khadhroony Solana Project.
|
||||
|
||||
## Responsabilités
|
||||
|
||||
La crate possède :
|
||||
|
||||
- les cinq niveaux KSP `error`, `warn`, `info`, `debug` et `trace` ;
|
||||
- les macros d'événements et de spans qui préservent le callsite du consommateur ;
|
||||
- `LoggingSettings` et les settings console/fichier indépendants de Config ;
|
||||
- l'installation unique du subscriber global ;
|
||||
- le hot reload via `reinitialize` sans second subscriber global ;
|
||||
- le takeover des logs : les targets externes sont silencieux par défaut ;
|
||||
- les sorties console et fichier non bloquantes ;
|
||||
- les `WorkerGuard`, compteurs de lignes abandonnées, rotation fichier et stripping ANSI ;
|
||||
- l'instrumentation de scopes synchrones et de `Future` async.
|
||||
|
||||
## Frontières
|
||||
|
||||
Une crate KSP comportementale qui journalise son activité dépend de `ksp-logging-lib` et n'utilise pas directement `tracing`, `tracing-subscriber` ou `tracing-appender`.
|
||||
|
||||
Les événements utiles issus d'une dépendance externe ne sont pas renommés : la crate KSP propriétaire de l'opération réémet explicitement l'information utile sous son propre target KSP.
|
||||
|
||||
`ksp-logging-lib` ne dépend pas de `ksp-config-lib`. Config pourra construire un `LoggingSettings` puis appeler `initialize` ou `reinitialize`.
|
||||
|
||||
## Documentation
|
||||
|
||||
- [`USAGE.md`](USAGE.md) — utilisation concrète de la façade et du runtime ;
|
||||
- [`TODO.md`](TODO.md) — capacités explicitement différées ou points restant à fermer.
|
||||
22
crates/ksp-logging-lib/TODO.md
Normal file
22
crates/ksp-logging-lib/TODO.md
Normal file
@@ -0,0 +1,22 @@
|
||||
<!-- file: crates/ksp-logging-lib/TODO.md -->
|
||||
<!-- version: 1 -->
|
||||
|
||||
# TODO ksp-logging-lib
|
||||
|
||||
## À fermer avant la stable 0.1.2
|
||||
|
||||
- exécuter les validations Cargo complètes de `pre.005` puis de la tranche finale ;
|
||||
- exécuter explicitement le probe d'overhead ignoré et conserver son résultat dans le delta de validation approprié ;
|
||||
- vérifier une dernière fois le graphe de dépendances/features et l'absence de contournement de la façade KSP ;
|
||||
- synchroniser la documentation finale et le prompt `0.1.3 — ksp-config-lib`.
|
||||
|
||||
## Capacités différées
|
||||
|
||||
Ces éléments ne font pas partie du contrat `0.1.2` et ne doivent être ajoutés qu'après besoin concret :
|
||||
|
||||
- plusieurs routes fichier indépendantes ;
|
||||
- rotation par taille, rétention/compression et symlink `latest` ;
|
||||
- formats JSON ou autres formats structurés alternatifs ;
|
||||
- OpenTelemetry/export réseau ;
|
||||
- watcher de fichiers de configuration, qui appartient à Config ou à une couche supérieure ;
|
||||
- benchmark/profiling de précision destiné aux chemins de trading sensibles à la latence.
|
||||
118
crates/ksp-logging-lib/USAGE.md
Normal file
118
crates/ksp-logging-lib/USAGE.md
Normal file
@@ -0,0 +1,118 @@
|
||||
<!-- file: crates/ksp-logging-lib/USAGE.md -->
|
||||
<!-- version: 1 -->
|
||||
|
||||
# Utilisation de ksp-logging-lib
|
||||
|
||||
## Target d'une crate consommatrice
|
||||
|
||||
Chaque crate KSP comportementale fournit explicitement son target, égal au nom Cargo de la crate :
|
||||
|
||||
```rust
|
||||
const LOGGING_TARGET: &str = "ksp-store-lib";
|
||||
|
||||
ksp_logging_lib::trace!(
|
||||
target: LOGGING_TARGET,
|
||||
domain = "store",
|
||||
component = "postgres",
|
||||
operation = "load_transactions",
|
||||
"executing store operation"
|
||||
);
|
||||
```
|
||||
|
||||
Les champs `domain`, `component`, `operation` et autres champs structurés sont ajoutés par le caller lorsqu'ils sont utiles ; ils ne remplacent pas le target propriétaire.
|
||||
|
||||
## Initialisation
|
||||
|
||||
`initialize` installe le subscriber global KSP une seule fois et retourne le `LoggingGuard` qui doit rester vivant pendant la durée du runtime :
|
||||
|
||||
```rust
|
||||
let settings = ksp_logging_lib::LoggingSettings::new(
|
||||
ksp_logging_lib::LogFilterLevel::Info,
|
||||
ksp_logging_lib::SpanEvents::NewAndClose,
|
||||
std::option::Option::Some(ksp_logging_lib::ConsoleSettings::stderr()),
|
||||
std::option::Option::Some(ksp_logging_lib::FileSettings::new(
|
||||
"logs",
|
||||
"worker.log",
|
||||
ksp_logging_lib::FileRotation::Daily,
|
||||
)),
|
||||
);
|
||||
|
||||
let initialize_result = ksp_logging_lib::initialize(&settings);
|
||||
let mut logging_guard = match initialize_result {
|
||||
std::result::Result::Ok(guard) => guard,
|
||||
std::result::Result::Err(error) => return std::result::Result::Err(error),
|
||||
};
|
||||
```
|
||||
|
||||
Une configuration sans console ni fichier est valide et installe une infrastructure initialement silencieuse qui pourra être activée plus tard par hot reload.
|
||||
|
||||
## Hot reload
|
||||
|
||||
Une nouvelle configuration peut être appliquée sans redémarrer le processus ou le worker :
|
||||
|
||||
```rust
|
||||
let debug_settings = ksp_logging_lib::LoggingSettings::new(
|
||||
ksp_logging_lib::LogFilterLevel::Info,
|
||||
ksp_logging_lib::SpanEvents::NewAndClose,
|
||||
std::option::Option::Some(ksp_logging_lib::ConsoleSettings::stderr()),
|
||||
std::option::Option::None,
|
||||
)
|
||||
.with_target_filter(ksp_logging_lib::TargetFilter::new(
|
||||
"ksp-store-lib",
|
||||
ksp_logging_lib::LogFilterLevel::Debug,
|
||||
));
|
||||
|
||||
let reload_result = ksp_logging_lib::reinitialize(&mut logging_guard, &debug_settings);
|
||||
if let std::result::Result::Err(error) = reload_result {
|
||||
return std::result::Result::Err(error);
|
||||
}
|
||||
```
|
||||
|
||||
La nouvelle configuration est préparée avant la bascule. Si sa validation ou la création d'un nouveau sink échoue, l'ancienne configuration reste active.
|
||||
|
||||
## Spans synchrones
|
||||
|
||||
```rust
|
||||
let span = ksp_logging_lib::trace_span!(
|
||||
target: LOGGING_TARGET,
|
||||
"materialize_transaction",
|
||||
domain = "store"
|
||||
);
|
||||
|
||||
let output = span.in_scope(|| {
|
||||
return materialize_transaction();
|
||||
});
|
||||
```
|
||||
|
||||
Avec `SpanEvents::NewAndClose`, le formatter produit les événements de création/fermeture et les temps `busy` / `idle` à la fermeture.
|
||||
|
||||
## Spans async
|
||||
|
||||
Une `Future` doit être instrumentée avec `ksp_logging_lib::instrument` ; un guard d'entrée de span ne doit pas être conservé à travers `.await` :
|
||||
|
||||
```rust
|
||||
let span = ksp_logging_lib::trace_span!(
|
||||
target: LOGGING_TARGET,
|
||||
"fetch_account",
|
||||
domain = "transport"
|
||||
);
|
||||
|
||||
let output = ksp_logging_lib::instrument(span, fetch_account()).await;
|
||||
```
|
||||
|
||||
La future instrumentée entre/sort du span pendant ses polls et lors de son `Drop`, conformément au contrat de la primitive `tracing` sous-jacente.
|
||||
|
||||
## Lignes abandonnées
|
||||
|
||||
Les sorties utilisent des queues lossy afin de ne pas appliquer de backpressure au hot path. Les pertes restent observables :
|
||||
|
||||
```rust
|
||||
let dropped = logging_guard.dropped_lines();
|
||||
ksp_logging_lib::warn!(
|
||||
target: LOGGING_TARGET,
|
||||
console = dropped.console(),
|
||||
file = dropped.file(),
|
||||
total = dropped.total(),
|
||||
"logging queues dropped lines"
|
||||
);
|
||||
```
|
||||
@@ -1,5 +1,5 @@
|
||||
// file: crates/ksp-logging-lib/src/lib.rs
|
||||
// version: 3
|
||||
// version: 4
|
||||
#![warn(missing_docs)]
|
||||
#![deny(unreachable_pub)]
|
||||
#![forbid(unsafe_code)]
|
||||
@@ -7,8 +7,9 @@
|
||||
//! KSP-owned logging and tracing facade.
|
||||
//!
|
||||
//! This crate owns the KSP runtime logging contract. Behavioral KSP crates emit events and spans through this facade rather than depending directly on the
|
||||
//! `tracing` stack. `0.1.2-pre.004` owns the single global subscriber, KSP takeover filtering, hot reload, non-blocking console/file outputs, rolling file
|
||||
//! appenders, ANSI stripping, dropped-line counters and the worker guards required to flush active queues.
|
||||
//! `tracing` stack. `0.1.2-pre.005` owns the single global subscriber, KSP takeover filtering, hot reload, non-blocking console/file outputs, rolling file
|
||||
//! appenders, ANSI stripping, dropped-line counters and the worker guards required to flush active queues. The integration surface is hardened by
|
||||
//! deterministic saturation, concurrent reload and ownership audits before final release validation.
|
||||
|
||||
mod error;
|
||||
mod macros;
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
// file: crates/ksp-logging-lib/src/runtime.rs
|
||||
// version: 7
|
||||
// version: 8
|
||||
|
||||
use tracing_subscriber::Layer; // rust-rules: trait-import
|
||||
use tracing_subscriber::layer::SubscriberExt; // rust-rules: trait-import
|
||||
@@ -224,12 +224,16 @@ fn build_non_blocking_output<W>(writer: W, thread_name: &str, settings: &crate::
|
||||
where
|
||||
W: std::io::Write + std::marker::Send + 'static,
|
||||
{
|
||||
let (non_blocking, worker_guard) = tracing_appender::non_blocking::NonBlockingBuilder::default().lossy(true).thread_name(thread_name).finish(writer);
|
||||
let (non_blocking, worker_guard) = non_blocking_builder(thread_name).finish(writer);
|
||||
let error_counter = non_blocking.error_counter();
|
||||
let layer = build_format_layer(non_blocking, settings, ansi_sanitization);
|
||||
return PreparedOutput { layer, output: RuntimeOutput { _worker_guard: worker_guard, error_counter } };
|
||||
}
|
||||
|
||||
fn non_blocking_builder(thread_name: &str) -> tracing_appender::non_blocking::NonBlockingBuilder {
|
||||
return tracing_appender::non_blocking::NonBlockingBuilder::default().lossy(true).thread_name(thread_name);
|
||||
}
|
||||
|
||||
fn build_format_layer(writer: tracing_appender::non_blocking::NonBlocking, settings: &crate::LoggingSettings, ansi_sanitization: bool) -> BoxedRuntimeLayer {
|
||||
return tracing_subscriber::fmt::layer()
|
||||
.with_writer(writer)
|
||||
|
||||
47
crates/ksp-logging-lib/tests/overhead.rs
Normal file
47
crates/ksp-logging-lib/tests/overhead.rs
Normal file
@@ -0,0 +1,47 @@
|
||||
// file: crates/ksp-logging-lib/tests/overhead.rs
|
||||
// version: 1
|
||||
|
||||
//! Diagnostic gross-overhead probe for the reload layer used by KSP Logging.
|
||||
|
||||
use tracing_subscriber::layer::SubscriberExt; // rust-rules: trait-import
|
||||
|
||||
const TEST_TARGET: &str = "ksp-logging-lib";
|
||||
const ITERATIONS: u64 = 200_000;
|
||||
|
||||
fn emit_probe_events() {
|
||||
for sequence in 0..ITERATIONS {
|
||||
tracing::trace!(target: TEST_TARGET, sequence, "reload overhead probe");
|
||||
}
|
||||
}
|
||||
|
||||
fn trace_filter() -> tracing_subscriber::filter::Targets {
|
||||
return tracing_subscriber::filter::Targets::new()
|
||||
.with_default(tracing_subscriber::filter::LevelFilter::OFF)
|
||||
.with_target(TEST_TARGET, tracing_subscriber::filter::LevelFilter::TRACE);
|
||||
}
|
||||
|
||||
#[test]
|
||||
#[ignore = "diagnostic timing probe; run explicitly with --ignored --nocapture"]
|
||||
fn reload_layer_overhead_remains_within_a_gross_regression_guardrail() {
|
||||
let baseline_subscriber = tracing_subscriber::registry().with(trace_filter());
|
||||
let baseline_start = std::time::Instant::now();
|
||||
tracing::subscriber::with_default(baseline_subscriber, || {
|
||||
emit_probe_events();
|
||||
return;
|
||||
});
|
||||
let baseline_elapsed = baseline_start.elapsed();
|
||||
let (reload_layer, _reload_handle) = tracing_subscriber::reload::Layer::new(trace_filter());
|
||||
let reload_subscriber = tracing_subscriber::registry().with(reload_layer);
|
||||
let reload_start = std::time::Instant::now();
|
||||
tracing::subscriber::with_default(reload_subscriber, || {
|
||||
emit_probe_events();
|
||||
return;
|
||||
});
|
||||
let reload_elapsed = reload_start.elapsed();
|
||||
let gross_ceiling = baseline_elapsed.saturating_mul(100).saturating_add(std::time::Duration::from_millis(100));
|
||||
println!("KSP reload overhead probe: baseline={baseline_elapsed:?}, reload={reload_elapsed:?}, iterations={ITERATIONS}");
|
||||
assert!(
|
||||
reload_elapsed <= gross_ceiling,
|
||||
"reload layer exceeded the gross regression guardrail: baseline={baseline_elapsed:?}, reload={reload_elapsed:?}"
|
||||
);
|
||||
}
|
||||
81
crates/ksp-logging-lib/tests/ownership.rs
Normal file
81
crates/ksp-logging-lib/tests/ownership.rs
Normal file
@@ -0,0 +1,81 @@
|
||||
// file: crates/ksp-logging-lib/tests/ownership.rs
|
||||
// version: 1
|
||||
|
||||
//! Integration audit ensuring KSP crates do not bypass the logging facade.
|
||||
|
||||
fn collect_rust_files(directory: &std::path::Path, files: &mut std::vec::Vec<std::path::PathBuf>) {
|
||||
let entries_result = std::fs::read_dir(directory);
|
||||
let entries = match entries_result {
|
||||
std::result::Result::Ok(entries) => entries,
|
||||
std::result::Result::Err(_) => return,
|
||||
};
|
||||
for entry_result in entries {
|
||||
let entry = match entry_result {
|
||||
std::result::Result::Ok(entry) => entry,
|
||||
std::result::Result::Err(_) => continue,
|
||||
};
|
||||
let path = entry.path();
|
||||
if path.is_dir() {
|
||||
collect_rust_files(path.as_path(), files);
|
||||
continue;
|
||||
}
|
||||
if path.extension().and_then(std::ffi::OsStr::to_str) == std::option::Option::Some("rs") {
|
||||
files.push(path);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn workspace_crates_do_not_bypass_ksp_logging_facade() {
|
||||
let logging_manifest_directory = std::path::PathBuf::from(env!("CARGO_MANIFEST_DIR"));
|
||||
let workspace_root = match logging_manifest_directory.parent().and_then(std::path::Path::parent) {
|
||||
std::option::Option::Some(root) => root,
|
||||
std::option::Option::None => return,
|
||||
};
|
||||
let crates_directory = workspace_root.join("crates");
|
||||
let entries_result = std::fs::read_dir(crates_directory.as_path());
|
||||
assert!(entries_result.is_ok(), "unable to inspect workspace crates at {}", crates_directory.display());
|
||||
let entries = match entries_result {
|
||||
std::result::Result::Ok(entries) => entries,
|
||||
std::result::Result::Err(_) => return,
|
||||
};
|
||||
for entry_result in entries {
|
||||
let entry = match entry_result {
|
||||
std::result::Result::Ok(entry) => entry,
|
||||
std::result::Result::Err(_) => continue,
|
||||
};
|
||||
let crate_path = entry.path();
|
||||
if !crate_path.is_dir() || entry.file_name() == std::ffi::OsStr::new("ksp-logging-lib") {
|
||||
continue;
|
||||
}
|
||||
let manifest_path = crate_path.join("Cargo.toml");
|
||||
if manifest_path.exists() {
|
||||
let manifest_result = std::fs::read_to_string(manifest_path.as_path());
|
||||
assert!(manifest_result.is_ok(), "unable to read {}", manifest_path.display());
|
||||
let manifest = match manifest_result {
|
||||
std::result::Result::Ok(manifest) => manifest,
|
||||
std::result::Result::Err(_) => continue,
|
||||
};
|
||||
assert!(
|
||||
!manifest.contains("tracing.workspace") && !manifest.contains("\ntracing =") && !manifest.contains("[dependencies.tracing]"),
|
||||
"{} depends directly on tracing",
|
||||
manifest_path.display(),
|
||||
);
|
||||
assert!(!manifest.contains("tracing-subscriber"), "{} depends directly on tracing-subscriber", manifest_path.display());
|
||||
assert!(!manifest.contains("tracing-appender"), "{} depends directly on tracing-appender", manifest_path.display());
|
||||
}
|
||||
let mut rust_files = std::vec::Vec::new();
|
||||
collect_rust_files(crate_path.as_path(), &mut rust_files);
|
||||
for rust_file in rust_files {
|
||||
let source_result = std::fs::read_to_string(rust_file.as_path());
|
||||
assert!(source_result.is_ok(), "unable to read {}", rust_file.display());
|
||||
let source = match source_result {
|
||||
std::result::Result::Ok(source) => source,
|
||||
std::result::Result::Err(_) => continue,
|
||||
};
|
||||
assert!(!source.contains("tracing::"), "{} bypasses ksp-logging-lib via tracing", rust_file.display());
|
||||
assert!(!source.contains("tracing_subscriber::"), "{} bypasses ksp-logging-lib via tracing-subscriber", rust_file.display());
|
||||
assert!(!source.contains("tracing_appender::"), "{} bypasses ksp-logging-lib via tracing-appender", rust_file.display());
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -1,5 +1,5 @@
|
||||
// file: crates/ksp-logging-lib/tests/runtime.rs
|
||||
// version: 2
|
||||
// version: 3
|
||||
|
||||
//! Integration tests for global initialization, takeover filtering, non-blocking outputs and hot reload.
|
||||
|
||||
@@ -62,6 +62,50 @@ fn read_directory_text(path: &std::path::Path) -> std::string::String {
|
||||
return output;
|
||||
}
|
||||
|
||||
fn exercise_concurrent_reload(guard: &mut ksp_logging_lib::LoggingGuard, disabled: &ksp_logging_lib::LoggingSettings) {
|
||||
let quiet_console = ksp_logging_lib::LoggingSettings::new(
|
||||
ksp_logging_lib::LogFilterLevel::Off,
|
||||
ksp_logging_lib::SpanEvents::Off,
|
||||
std::option::Option::Some(ksp_logging_lib::ConsoleSettings::stderr()),
|
||||
std::option::Option::None,
|
||||
);
|
||||
let stop = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false));
|
||||
let barrier = std::sync::Arc::new(std::sync::Barrier::new(5));
|
||||
let mut threads = std::vec::Vec::new();
|
||||
for worker_index in 0..4_u32 {
|
||||
let worker_stop = std::sync::Arc::clone(&stop);
|
||||
let worker_barrier = std::sync::Arc::clone(&barrier);
|
||||
threads.push(std::thread::spawn(move || {
|
||||
worker_barrier.wait();
|
||||
let mut sequence = 0_u64;
|
||||
while !worker_stop.load(std::sync::atomic::Ordering::Relaxed) {
|
||||
ksp_logging_lib::trace!(target: LOGGING_TARGET, worker_index, sequence, "concurrent reload probe");
|
||||
sequence = sequence.wrapping_add(1);
|
||||
}
|
||||
return;
|
||||
}));
|
||||
}
|
||||
barrier.wait();
|
||||
let mut reloads_succeeded = true;
|
||||
for reload_index in 0..32_u32 {
|
||||
let settings = if reload_index % 2 == 0 { &quiet_console } else { disabled };
|
||||
let reload_result = ksp_logging_lib::reinitialize(guard, settings);
|
||||
if reload_result.is_err() {
|
||||
reloads_succeeded = false;
|
||||
break;
|
||||
}
|
||||
}
|
||||
stop.store(true, std::sync::atomic::Ordering::Relaxed);
|
||||
let mut joins_succeeded = true;
|
||||
for thread in threads {
|
||||
if thread.join().is_err() {
|
||||
joins_succeeded = false;
|
||||
}
|
||||
}
|
||||
assert!(reloads_succeeded);
|
||||
assert!(joins_succeeded);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn global_runtime_supports_takeover_non_blocking_outputs_hot_reload_and_single_initialization() {
|
||||
let root = test_root_directory();
|
||||
@@ -117,6 +161,7 @@ fn global_runtime_supports_takeover_non_blocking_outputs_hot_reload_and_single_i
|
||||
assert_eq!(guard.settings(), &console_enabled);
|
||||
assert!(logging_trace_enabled());
|
||||
assert!(!external_error_enabled());
|
||||
exercise_concurrent_reload(&mut guard, &disabled);
|
||||
let log_directory = root.join("logs");
|
||||
let file_enabled = ksp_logging_lib::LoggingSettings::new(
|
||||
ksp_logging_lib::LogFilterLevel::Info,
|
||||
|
||||
73
crates/ksp-logging-lib/tests/span_lifecycle.rs
Normal file
73
crates/ksp-logging-lib/tests/span_lifecycle.rs
Normal file
@@ -0,0 +1,73 @@
|
||||
// file: crates/ksp-logging-lib/tests/span_lifecycle.rs
|
||||
// version: 1
|
||||
|
||||
//! Integration tests for formatted KSP span lifecycle timing output.
|
||||
|
||||
use tracing_subscriber::layer::SubscriberExt; // rust-rules: trait-import
|
||||
|
||||
const TEST_TARGET: &str = "ksp-logging-lib";
|
||||
|
||||
#[derive(Clone)]
|
||||
struct SharedWriter {
|
||||
buffer: std::sync::Arc<std::sync::Mutex<std::vec::Vec<u8>>>,
|
||||
}
|
||||
|
||||
impl SharedWriter {
|
||||
fn new(buffer: std::sync::Arc<std::sync::Mutex<std::vec::Vec<u8>>>) -> Self {
|
||||
return Self { buffer };
|
||||
}
|
||||
}
|
||||
|
||||
impl std::io::Write for SharedWriter {
|
||||
fn write(&mut self, bytes: &[u8]) -> std::io::Result<usize> {
|
||||
let lock_result = self.buffer.lock();
|
||||
let mut buffer = match lock_result {
|
||||
std::result::Result::Ok(buffer) => buffer,
|
||||
std::result::Result::Err(_) => return std::result::Result::Err(std::io::Error::other("span test buffer is poisoned")),
|
||||
};
|
||||
buffer.extend_from_slice(bytes);
|
||||
return std::result::Result::Ok(bytes.len());
|
||||
}
|
||||
|
||||
fn flush(&mut self) -> std::io::Result<()> {
|
||||
return std::result::Result::Ok(());
|
||||
}
|
||||
}
|
||||
|
||||
fn captured_text(buffer: &std::sync::Arc<std::sync::Mutex<std::vec::Vec<u8>>>) -> std::string::String {
|
||||
let lock_result = buffer.lock();
|
||||
let bytes = match lock_result {
|
||||
std::result::Result::Ok(bytes) => bytes.clone(),
|
||||
std::result::Result::Err(error) => error.into_inner().clone(),
|
||||
};
|
||||
return std::string::String::from_utf8_lossy(bytes.as_slice()).into_owned();
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn new_and_close_span_events_expose_busy_and_idle_timing_fields() {
|
||||
let buffer = std::sync::Arc::new(std::sync::Mutex::new(std::vec::Vec::new()));
|
||||
let writer_buffer = std::sync::Arc::clone(&buffer);
|
||||
let layer = tracing_subscriber::fmt::layer()
|
||||
.with_writer(move || -> SharedWriter {
|
||||
return SharedWriter::new(std::sync::Arc::clone(&writer_buffer));
|
||||
})
|
||||
.with_ansi(false)
|
||||
.with_target(true)
|
||||
.with_span_events(tracing_subscriber::fmt::format::FmtSpan::NEW | tracing_subscriber::fmt::format::FmtSpan::CLOSE);
|
||||
let subscriber = tracing_subscriber::registry().with(layer);
|
||||
tracing::subscriber::with_default(subscriber, || {
|
||||
let span = ksp_logging_lib::trace_span!(target: TEST_TARGET, "timed_scope", domain = "logging");
|
||||
span.in_scope(|| {
|
||||
std::hint::black_box(42_u32);
|
||||
return;
|
||||
});
|
||||
drop(span);
|
||||
return;
|
||||
});
|
||||
let text = captured_text(&buffer);
|
||||
assert!(text.contains("timed_scope"));
|
||||
assert!(text.contains("new"));
|
||||
assert!(text.contains("close"));
|
||||
assert!(text.contains("time.busy"));
|
||||
assert!(text.contains("time.idle"));
|
||||
}
|
||||
@@ -1,5 +1,5 @@
|
||||
// file: crates/ksp-logging-lib/unit_tests/runtime.rs
|
||||
// version: 4
|
||||
// version: 5
|
||||
|
||||
#[test]
|
||||
fn level_mapping_covers_all_ksp_levels() {
|
||||
@@ -88,3 +88,107 @@ fn dropped_line_snapshots_add_saturating_by_sink() {
|
||||
assert_eq!(combined.file(), 11);
|
||||
assert_eq!(combined.total(), usize::MAX);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn takeover_filter_prefers_more_specific_ksp_prefixes_and_supports_off() {
|
||||
let settings = crate::LoggingSettings::new(crate::LogFilterLevel::Info, crate::SpanEvents::Off, std::option::Option::None, std::option::Option::None)
|
||||
.with_target_filter(crate::TargetFilter::new("ksp-store-", crate::LogFilterLevel::Debug))
|
||||
.with_target_filter(crate::TargetFilter::new("ksp-store-lib", crate::LogFilterLevel::Trace))
|
||||
.with_target_filter(crate::TargetFilter::new("ksp-wallet-lib", crate::LogFilterLevel::Off));
|
||||
let filter = super::build_target_filter(&settings);
|
||||
assert!(filter.would_enable("ksp-store-other", &tracing::Level::DEBUG));
|
||||
assert!(!filter.would_enable("ksp-store-other", &tracing::Level::TRACE));
|
||||
assert!(filter.would_enable("ksp-store-lib", &tracing::Level::TRACE));
|
||||
assert!(!filter.would_enable("ksp-wallet-lib", &tracing::Level::ERROR));
|
||||
}
|
||||
|
||||
struct BlockingWriter {
|
||||
first_write: bool,
|
||||
started: std::sync::mpsc::SyncSender<()>,
|
||||
release: std::sync::Arc<(std::sync::Mutex<bool>, std::sync::Condvar)>,
|
||||
}
|
||||
|
||||
impl BlockingWriter {
|
||||
fn new(started: std::sync::mpsc::SyncSender<()>, release: std::sync::Arc<(std::sync::Mutex<bool>, std::sync::Condvar)>) -> Self {
|
||||
return Self { first_write: true, started, release };
|
||||
}
|
||||
}
|
||||
|
||||
impl std::io::Write for BlockingWriter {
|
||||
fn write(&mut self, buffer: &[u8]) -> std::io::Result<usize> {
|
||||
if self.first_write {
|
||||
self.first_write = false;
|
||||
if self.started.send(()).is_err() {
|
||||
return std::result::Result::Err(std::io::Error::other("unable to notify saturation test that the writer is blocked"));
|
||||
}
|
||||
let (lock, condition) = self.release.as_ref();
|
||||
let lock_result = lock.lock();
|
||||
let mut released = match lock_result {
|
||||
std::result::Result::Ok(released) => released,
|
||||
std::result::Result::Err(_) => {
|
||||
return std::result::Result::Err(std::io::Error::other("saturation test release lock is poisoned"));
|
||||
},
|
||||
};
|
||||
while !*released {
|
||||
let wait_result = condition.wait(released);
|
||||
released = match wait_result {
|
||||
std::result::Result::Ok(released) => released,
|
||||
std::result::Result::Err(_) => {
|
||||
return std::result::Result::Err(std::io::Error::other("saturation test release wait is poisoned"));
|
||||
},
|
||||
};
|
||||
}
|
||||
}
|
||||
return std::result::Result::Ok(buffer.len());
|
||||
}
|
||||
|
||||
fn flush(&mut self) -> std::io::Result<()> {
|
||||
return std::result::Result::Ok(());
|
||||
}
|
||||
}
|
||||
|
||||
fn release_blocked_writer(release: &std::sync::Arc<(std::sync::Mutex<bool>, std::sync::Condvar)>) {
|
||||
let (lock, condition) = release.as_ref();
|
||||
let lock_result = lock.lock();
|
||||
let mut released = match lock_result {
|
||||
std::result::Result::Ok(released) => released,
|
||||
std::result::Result::Err(error) => error.into_inner(),
|
||||
};
|
||||
*released = true;
|
||||
condition.notify_all();
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn lossy_non_blocking_builder_drops_lines_instead_of_blocking_a_stalled_producer() {
|
||||
let (started_sender, started_receiver) = std::sync::mpsc::sync_channel(1);
|
||||
let release = std::sync::Arc::new((std::sync::Mutex::new(false), std::sync::Condvar::new()));
|
||||
let writer = BlockingWriter::new(started_sender, std::sync::Arc::clone(&release));
|
||||
let (mut non_blocking, worker_guard) = super::non_blocking_builder("ksp-logging-saturation-test").buffered_lines_limit(1).finish(writer);
|
||||
let error_counter = non_blocking.error_counter();
|
||||
let first_write = std::io::Write::write_all(&mut non_blocking, b"block worker\n");
|
||||
assert!(first_write.is_ok());
|
||||
let writer_started = started_receiver.recv_timeout(std::time::Duration::from_secs(2));
|
||||
assert!(writer_started.is_ok());
|
||||
let mut producer = non_blocking.clone();
|
||||
let (finished_sender, finished_receiver) = std::sync::mpsc::sync_channel(1);
|
||||
let producer_thread = std::thread::spawn(move || {
|
||||
let mut succeeded = true;
|
||||
for _ in 0..1_024 {
|
||||
let write_result = std::io::Write::write_all(&mut producer, b"queued line\n");
|
||||
if write_result.is_err() {
|
||||
succeeded = false;
|
||||
break;
|
||||
}
|
||||
}
|
||||
let _send_result = finished_sender.send(succeeded);
|
||||
return;
|
||||
});
|
||||
let producer_finished = finished_receiver.recv_timeout(std::time::Duration::from_secs(2));
|
||||
release_blocked_writer(&release);
|
||||
let join_result = producer_thread.join();
|
||||
assert!(join_result.is_ok());
|
||||
assert_eq!(producer_finished, std::result::Result::Ok(true));
|
||||
assert!(error_counter.dropped_lines() > 0);
|
||||
drop(non_blocking);
|
||||
drop(worker_guard);
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user