commit d926039351d28e36b13b51bcd2864b005dcb22de
parent 1afd5eec11621049a1abeb930e77b5cddb749222
Author: Antoine A <>
Date: Sat, 23 May 2026 13:41:49 +0200
common: improve and optimize logging
Diffstat:
7 files changed, 153 insertions(+), 72 deletions(-)
diff --git a/common/taler-api/Cargo.toml b/common/taler-api/Cargo.toml
@@ -16,6 +16,7 @@ dashmap = "6.1"
http-body-util.workspace = true
zlib-rs = "0.6.3"
tokio = { workspace = true, features = ["signal"] }
+rand.workspace = true
serde.workspace = true
serde_json.workspace = true
serde_urlencoded.workspace = true
diff --git a/common/taler-api/src/api.rs b/common/taler-api/src/api.rs
@@ -27,13 +27,16 @@ use axum::{
middleware::{self, Next},
response::Response,
};
+use compact_str::CompactString;
+use rand::RngExt as _;
use revenue::Revenue;
use taler_common::{
error_code::ErrorCode,
+ log::LOG_TASK_ID,
types::amount::{Amount, Currency},
};
use tokio::signal;
-use tracing::{Level, info};
+use tracing::{Level, debug, info};
use wire::WireGateway;
use crate::{
@@ -220,44 +223,57 @@ macro_rules! dyn_event {
/** Taler API logger */
async fn logger_middleware(request: Request, next: Next) -> Response {
- let request_info = format!(
- "{} {}",
- request.method(),
- request
- .uri()
- .path_and_query()
- .map(|it| it.as_str())
- .unwrap_or_default()
- );
let now = Instant::now();
- let response = next.run(request).await;
- let elapsed = now.elapsed();
- let status = response.status();
- let level = match status.as_u16() {
- 400..500 => Level::WARN,
- 500..600 => Level::ERROR,
- _ => Level::INFO,
+ let request_id: compact_str::CompactString = {
+ let charset = b"ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789";
+ let mut rng = rand::rng();
+
+ let mut ansi = [0u8; 10];
+ for c in ansi.iter_mut() {
+ let idx = rng.random_range(0..charset.len());
+ *c = charset[idx];
+ }
+ unsafe { CompactString::from_utf8_unchecked(ansi) }
};
+ let method = request.method().clone();
+ let path_and_query = request.uri().path_and_query().cloned();
+ let path_and_query = path_and_query
+ .as_ref()
+ .map(|it| it.as_str())
+ .unwrap_or_default();
+ LOG_TASK_ID
+ .scope(request_id, async {
+ debug!(target: "api", "{method} {path_and_query}");
+ let response = next.run(request).await;
+ let elapsed = now.elapsed();
+ let status = response.status();
+ let level = match status.as_u16() {
+ 400..500 => Level::WARN,
+ 500..600 => Level::ERROR,
+ _ => Level::INFO,
+ };
- if let Some(log) = response.extensions().get::<LoggedError>() {
- let LoggedError { code, info } = log;
- dyn_event!(level, target: "api",
- "{} {request_info} {}ms: {code}{}",
- response.status(),
- elapsed.as_millis(),
- std::fmt::from_fn(|f|{
- if let Some(info) = info {
- write!(f, " {info}")?;
- }
- Ok(())
- })
- );
- } else {
- dyn_event!(level, target: "api",
- "{} {request_info} {}ms",
- response.status(),
- elapsed.as_millis()
- );
- }
- response
+ if let Some(log) = response.extensions().get::<LoggedError>() {
+ let LoggedError { code, info } = log;
+ dyn_event!(level, target: "api",
+ "{} {method} {path_and_query} {}ms: {code}{}",
+ response.status(),
+ elapsed.as_millis(),
+ std::fmt::from_fn(|f|{
+ if let Some(info) = info {
+ write!(f, " {info}")?;
+ }
+ Ok(())
+ })
+ );
+ } else {
+ dyn_event!(level, target: "api",
+ "{} {method} {path_and_query} {}ms",
+ response.status(),
+ elapsed.as_millis()
+ );
+ }
+ response
+ })
+ .await
}
diff --git a/common/taler-api/src/extract.rs b/common/taler-api/src/extract.rs
@@ -26,6 +26,7 @@ use axum::{
use http_body_util::BodyExt as _;
use serde::de::DeserializeOwned;
use taler_common::error_code::ErrorCode;
+use tracing::trace;
use url::form_urlencoded;
use zlib_rs::{InflateConfig, ReturnCode};
@@ -128,6 +129,7 @@ pub async fn decompressed_strict_body(headers: &HeaderMap, body: Body) -> ApiRes
} else {
bytes
};
+ trace!(target: "api", "req {}", String::from_utf8_lossy(&bytes));
Ok(bytes)
}
diff --git a/common/taler-api/src/notification.rs b/common/taler-api/src/notification.rs
@@ -34,7 +34,7 @@ macro_rules! notification_listener {
loop {
let notification = listener.recv().await?;
tracing::debug!(target: "db-watcher",
- "db notification: {} - {}",
+ "notif: {} - {}",
notification.channel(),
notification.payload()
);
@@ -46,7 +46,7 @@ macro_rules! notification_listener {
}
Err(e) => {
tracing::error!(target: "db-watcher",
- "db notification: {} {e} - {}",
+ "notif: {} {e} - {}",
notification.channel(),
notification.payload()
);
diff --git a/common/taler-common/src/lib.rs b/common/taler-common/src/lib.rs
@@ -47,6 +47,10 @@ pub struct CommonArgs {
/// Configure logging to use LOGLEVEL
#[arg(short('L'), long, global = true)]
log: Option<tracing::Level>,
+
+ /// Show logs from all sources
+ #[arg(short('V'), long, global = true)]
+ verbose: bool,
}
pub fn taler_main(
@@ -54,7 +58,7 @@ pub fn taler_main(
args: CommonArgs,
app: impl AsyncFnOnce(Config) -> Result<(), anyhow::Error>,
) {
- taler_logger(args.log).init();
+ taler_logger(args.log, args.verbose).init();
let cfg = match Config::from_file(src, args.config) {
Ok(cfg) => cfg,
Err(err) => {
diff --git a/common/taler-common/src/log.rs b/common/taler-common/src/log.rs
@@ -16,65 +16,122 @@
use std::io::IsTerminal;
+use compact_str::CompactString;
use jiff::{Timestamp, fmt::StdFmtWrite, tz::TimeZone};
-use tracing::Level;
-use tracing_subscriber::{fmt::time::FormatTime, layer::SubscriberExt, util::SubscriberInitExt};
+use tracing::{Event, Level, Subscriber};
+use tracing_subscriber::{
+ fmt::{FmtContext, FormatEvent, FormatFields, format::Writer},
+ layer::SubscriberExt,
+ registry::LookupSpan,
+ util::SubscriberInitExt,
+};
-pub struct TalerTime {
+tokio::task_local! {
+ pub static LOG_TASK_ID: CompactString;
+}
+
+pub struct TalerFmt {
zone: Option<TimeZone>,
}
-impl TalerTime {
- pub fn load() -> Self {
- let zone = if std::env::var_os("JOURNAL_STREAM").is_some() {
- None
- } else {
- Some(match TimeZone::try_system() {
- Ok(z) => z,
- Err(e) => {
- eprintln!("could not fetch system time zone, default to UTC: {e}");
- TimeZone::UTC
- }
- })
- };
- Self { zone }
+impl Default for TalerFmt {
+ fn default() -> Self {
+ Self {
+ zone: if std::env::var_os("JOURNAL_STREAM").is_some() {
+ None
+ } else {
+ Some(match TimeZone::try_system() {
+ Ok(z) => z,
+ Err(e) => {
+ eprintln!("could not fetch system time zone, default to UTC: {e}");
+ TimeZone::UTC
+ }
+ })
+ },
+ }
}
}
-impl FormatTime for TalerTime {
- fn format_time(&self, w: &mut tracing_subscriber::fmt::format::Writer<'_>) -> std::fmt::Result {
+impl<S, N> FormatEvent<S, N> for TalerFmt
+where
+ S: Subscriber + for<'a> LookupSpan<'a>,
+ N: for<'a> FormatFields<'a> + 'static,
+{
+ fn format_event(
+ &self,
+ ctx: &FmtContext<'_, S, N>,
+ mut w: Writer<'_>,
+ event: &Event<'_>,
+ ) -> std::fmt::Result {
+ let meta = event.metadata();
+ let ansi = w.has_ansi_escapes();
+
if let Some(zone) = &self.zone {
let timestamp = Timestamp::now();
let offset = zone.to_offset(timestamp);
+ if ansi {
+ write!(&mut w, "\x1b[2m")?; // Dim fg
+ }
jiff::fmt::temporal::DateTimePrinter::new()
.precision(Some(6))
.separator(b'T')
- .print_timestamp_with_offset(×tamp, offset, StdFmtWrite(w))
+ .print_timestamp_with_offset(×tamp, offset, StdFmtWrite(&mut w))
.map_err(|_| std::fmt::Error)?;
// TODO remove : in offset
}
- Ok(())
+ let level = meta.level();
+ if ansi {
+ let color = match *level {
+ tracing::Level::ERROR => "\x1b[31m", // red
+ tracing::Level::WARN => "\x1b[33m", // yellow
+ tracing::Level::INFO => "\x1b[32m", // green
+ tracing::Level::DEBUG => "\x1b[34m", // blue
+ tracing::Level::TRACE => "\x1b[35m", // magenta
+ };
+ write!(&mut w, "\x1b[0m{color}")?
+ };
+ let level = match *level {
+ tracing::Level::ERROR => "ERROR", // red
+ tracing::Level::WARN => " WARN", // yellow
+ tracing::Level::INFO => " INFO", // green
+ tracing::Level::DEBUG => "DEBUG", // blue
+ tracing::Level::TRACE => "TRACE", // magenta
+ };
+ write!(&mut w, " {level} ")?; // Reset dim then color
+ if ansi {
+ write!(&mut w, "\x1b[2;37m")?; // Dim fg
+ }
+ LOG_TASK_ID
+ .try_with(|id| write!(w, "({id})"))
+ .ok()
+ .transpose()?;
+ write!(w, "{}: ", meta.target())?;
+ if ansi {
+ write!(&mut w, "\x1b[0m")?; // Reset
+ }
+ ctx.format_fields(w.by_ref(), event)?;
+ writeln!(&mut w)
}
}
-pub fn taler_logger(max_level: Option<Level>) -> impl SubscriberInitExt {
+pub fn taler_logger(max_level: Option<Level>, verbose: bool) -> impl SubscriberInitExt {
let max_level = max_level.unwrap_or(Level::INFO);
tracing_subscriber::registry()
.with(
tracing_subscriber::fmt::layer()
- .compact()
+ .event_format(TalerFmt::default())
.with_writer(std::io::stderr)
- .with_timer(TalerTime::load())
.with_ansi(std::io::stderr().is_terminal()),
)
.with(tracing_subscriber::filter::filter_fn(move |metadata| {
let target = metadata.target();
*metadata.level() <= max_level
- && !(target.starts_with("sqlx")
- || target.contains("hyper_util")
- || target.starts_with("h2")
- || target.starts_with("reqwest")
- || target.starts_with("rustls")
- || target.starts_with("hyper_rustls"))
+ && (verbose
+ || !(target.starts_with("sqlx")
+ || target.contains("hyper_util")
+ || target.starts_with("h2")
+ || target.starts_with("reqwest")
+ || target.starts_with("rustls")
+ || target.starts_with("hyper_rustls")))
}))
}
diff --git a/common/taler-test-utils/src/lib.rs b/common/taler-test-utils/src/lib.rs
@@ -16,6 +16,7 @@
pub use axum::Router;
use taler_common::log::taler_logger;
+use tracing::Level;
use tracing_subscriber::util::SubscriberInitExt;
pub mod db;
@@ -24,5 +25,5 @@ pub mod routine;
pub mod server;
pub fn setup_tracing() {
- taler_logger(None).try_init().ok();
+ taler_logger(Some(Level::TRACE), false).try_init().ok();
}
