use std::collections::{BTreeMap, HashMap, VecDeque};
use std::fmt::Write as _;
use std::sync::atomic::{AtomicU8, Ordering};
use std::sync::{Arc, Mutex, OnceLock};
use serde::Serialize;
use tracing::field::{Field, Visit};
use tracing::{Event, Subscriber};
use tracing_subscriber::Layer;
use tracing_subscriber::layer::Context;
use tracing_subscriber::registry::LookupSpan;
pub const DEFAULT_CAPACITY: usize = 5_000;
pub const DEFAULT_MAX_BYTES: usize = 8 * 1024 * 1024;
pub const MAX_MESSAGE_BYTES: usize = 8 * 1024;
pub const MAX_FIELD_BYTES: usize = 2 * 1024;
pub const MAX_BACKTRACE_BYTES: usize = 16 * 1024;
#[derive(
Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, serde::Deserialize,
)]
#[serde(rename_all = "lowercase")]
pub enum LogLevel {
Trace,
Debug,
Info,
Warn,
Error,
}
impl LogLevel {
#[must_use]
pub fn parse(s: &str) -> Option<Self> {
match s.trim().to_ascii_lowercase().as_str() {
"trace" => Some(Self::Trace),
"debug" => Some(Self::Debug),
"info" => Some(Self::Info),
"warn" | "warning" => Some(Self::Warn),
"error" | "err" | "fatal" | "panic" => Some(Self::Error),
_ => None,
}
}
#[must_use]
pub const fn as_str(self) -> &'static str {
match self {
Self::Trace => "trace",
Self::Debug => "debug",
Self::Info => "info",
Self::Warn => "warn",
Self::Error => "error",
}
}
const fn from_tracing(level: tracing::Level) -> Self {
match level {
tracing::Level::TRACE => Self::Trace,
tracing::Level::DEBUG => Self::Debug,
tracing::Level::INFO => Self::Info,
tracing::Level::WARN => Self::Warn,
tracing::Level::ERROR => Self::Error,
}
}
const fn to_level_filter(self) -> tracing::level_filters::LevelFilter {
match self {
Self::Trace => tracing::level_filters::LevelFilter::TRACE,
Self::Debug => tracing::level_filters::LevelFilter::DEBUG,
Self::Info => tracing::level_filters::LevelFilter::INFO,
Self::Warn => tracing::level_filters::LevelFilter::WARN,
Self::Error => tracing::level_filters::LevelFilter::ERROR,
}
}
const fn from_log(level: log::Level) -> Self {
match level {
log::Level::Trace => Self::Trace,
log::Level::Debug => Self::Debug,
log::Level::Info => Self::Info,
log::Level::Warn => Self::Warn,
log::Level::Error => Self::Error,
}
}
const fn index(self) -> usize {
match self {
Self::Trace => 0,
Self::Debug => 1,
Self::Info => 2,
Self::Warn => 3,
Self::Error => 4,
}
}
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize)]
#[serde(rename_all = "snake_case")]
pub enum LogSource {
Tracing,
Log,
Panic,
}
#[derive(Debug, Clone, Serialize)]
#[non_exhaustive]
pub struct BackendLogEntry {
pub seq: u64,
pub ts_ms: u64,
pub level: LogLevel,
pub target: String,
pub message: String,
#[serde(skip_serializing_if = "serde_json::Map::is_empty")]
pub fields: serde_json::Map<String, serde_json::Value>,
#[serde(skip_serializing_if = "Vec::is_empty")]
pub spans: Vec<String>,
#[serde(skip_serializing_if = "Option::is_none")]
pub thread: Option<String>,
#[serde(skip_serializing_if = "Option::is_none")]
pub location: Option<String>,
pub source: LogSource,
}
impl BackendLogEntry {
#[cfg(test)]
pub(crate) fn for_tests(target: &str, message: &str) -> Self {
Self {
seq: 0,
ts_ms: now_ms(),
level: LogLevel::Info,
target: target.to_string(),
message: message.to_string(),
fields: serde_json::Map::new(),
spans: Vec::new(),
thread: None,
location: None,
source: LogSource::Tracing,
}
}
fn approx_bytes(&self) -> usize {
let fields: usize = self
.fields
.iter()
.map(|(k, v)| k.len() + value_len(v))
.sum();
let spans: usize = self.spans.iter().map(String::len).sum();
96 + self.target.len() + self.message.len() + fields + spans
}
#[must_use]
pub fn render(&self) -> String {
let secs = self.ts_ms / 1000;
let ms = self.ts_ms % 1000;
let (h, m, s) = ((secs / 3600) % 24, (secs / 60) % 60, secs % 60);
let mut out = format!(
"{h:02}:{m:02}:{s:02}.{ms:03}Z {:<5} {}: {}",
self.level.as_str().to_ascii_uppercase(),
self.target,
self.message
);
for (k, v) in &self.fields {
match v {
serde_json::Value::String(s) => {
let _ = write!(out, " {k}={s:?}");
}
other => {
let _ = write!(out, " {k}={other}");
}
}
}
out
}
}
fn value_len(v: &serde_json::Value) -> usize {
match v {
serde_json::Value::String(s) => s.len(),
_ => 16,
}
}
#[derive(Default)]
struct Ring {
entries: VecDeque<BackendLogEntry>,
next_seq: u64,
bytes: usize,
evicted: u64,
cleared_before: u64,
totals: [u64; 5],
}
impl Ring {
fn index_of(&self, seq: u64) -> usize {
self.entries.front().map_or(0, |front| {
usize::try_from(seq.saturating_sub(front.seq))
.unwrap_or(usize::MAX)
.min(self.entries.len())
})
}
fn evicted_since(&self, from: u64) -> u64 {
let oldest = self.entries.front().map_or(self.next_seq, |e| e.seq);
oldest.saturating_sub(from.max(self.cleared_before))
}
}
thread_local! {
static HOLDS_RING: std::cell::Cell<bool> = const { std::cell::Cell::new(false) };
}
struct RingGuard<'a>(std::sync::MutexGuard<'a, Ring>);
impl Drop for RingGuard<'_> {
fn drop(&mut self) {
HOLDS_RING.with(|h| h.set(false));
}
}
impl std::ops::Deref for RingGuard<'_> {
type Target = Ring;
fn deref(&self) -> &Ring {
&self.0
}
}
impl std::ops::DerefMut for RingGuard<'_> {
fn deref_mut(&mut self) -> &mut Ring {
&mut self.0
}
}
fn debug_bounded(value: &dyn std::fmt::Debug, max: usize) -> String {
struct Bounded {
out: String,
max: usize,
cut: bool,
}
impl std::fmt::Write for Bounded {
fn write_str(&mut self, s: &str) -> std::fmt::Result {
let room = self.max.saturating_sub(self.out.len());
if s.len() <= room {
self.out.push_str(s);
return Ok(());
}
let mut end = room;
while end > 0 && !s.is_char_boundary(end) {
end -= 1;
}
self.out.push_str(&s[..end]);
self.cut = true;
Err(std::fmt::Error)
}
}
let mut b = Bounded {
out: String::new(),
max,
cut: false,
};
let _ = write!(b, "{value:?}");
if b.cut {
b.out.push_str("…[truncated]");
}
b.out
}
thread_local! {
static IN_NOTIFY: std::cell::Cell<bool> = const { std::cell::Cell::new(false) };
}
struct NotifyScope(bool);
impl NotifyScope {
fn enter() -> Self {
Self(IN_NOTIFY.with(|f| f.replace(true)))
}
}
impl Drop for NotifyScope {
fn drop(&mut self) {
let previous = self.0;
IN_NOTIFY.with(|f| f.set(previous));
}
}
struct PollInNotifyScope<F>(F);
impl<F: std::future::Future + Unpin> std::future::Future for PollInNotifyScope<F> {
type Output = F::Output;
fn poll(
mut self: std::pin::Pin<&mut Self>,
cx: &mut std::task::Context<'_>,
) -> std::task::Poll<Self::Output> {
let _scope = NotifyScope::enter();
std::pin::Pin::new(&mut self.0).poll(cx)
}
}
pub struct LogBuffer {
ring: Mutex<Ring>,
notify: tokio::sync::Notify,
capacity: usize,
max_bytes: usize,
}
impl std::fmt::Debug for LogBuffer {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
f.debug_struct("LogBuffer")
.field("capacity", &self.capacity)
.field("max_bytes", &self.max_bytes)
.finish_non_exhaustive()
}
}
impl Default for LogBuffer {
fn default() -> Self {
Self::new(DEFAULT_CAPACITY, DEFAULT_MAX_BYTES)
}
}
impl LogBuffer {
#[must_use]
pub fn new(capacity: usize, max_bytes: usize) -> Self {
Self {
ring: Mutex::new(Ring::default()),
notify: tokio::sync::Notify::new(),
capacity: capacity.max(1),
max_bytes: max_bytes.max(1),
}
}
fn lock(&self) -> RingGuard<'_> {
let guard = self
.ring
.lock()
.unwrap_or_else(std::sync::PoisonError::into_inner);
HOLDS_RING.with(|h| h.set(true));
RingGuard(guard)
}
pub fn push(&self, entry: BackendLogEntry) {
if HOLDS_RING.with(std::cell::Cell::get) {
return;
}
let mut ring = self.lock();
Self::push_locked(&mut ring, entry, self.capacity, self.max_bytes);
drop(ring);
self.wake_waiters();
}
fn try_push(&self, entry: BackendLogEntry) -> bool {
if HOLDS_RING.with(std::cell::Cell::get) {
return false;
}
let mut ring = self.lock();
Self::push_locked(&mut ring, entry, self.capacity, self.max_bytes);
drop(ring);
self.wake_waiters();
true
}
fn push_locked(ring: &mut Ring, mut entry: BackendLogEntry, capacity: usize, max_bytes: usize) {
entry.seq = ring.next_seq;
ring.next_seq += 1;
ring.totals[entry.level.index()] += 1;
ring.bytes += entry.approx_bytes();
ring.entries.push_back(entry);
while ring.entries.len() > capacity || (ring.bytes > max_bytes && ring.entries.len() > 1) {
if let Some(old) = ring.entries.pop_front() {
ring.bytes = ring.bytes.saturating_sub(old.approx_bytes());
ring.evicted += 1;
}
}
}
fn wake_waiters(&self) {
if IN_NOTIFY.with(std::cell::Cell::get) {
return;
}
let _scope = NotifyScope::enter();
self.notify.notify_waiters();
}
#[must_use]
pub fn next_seq(&self) -> u64 {
self.lock().next_seq
}
#[must_use]
pub fn seq_at_or_after(&self, ts_ms: u64) -> u64 {
let ring = self.lock();
ring.entries
.iter()
.find(|e| e.ts_ms >= ts_ms)
.map_or(ring.next_seq, |e| e.seq)
}
#[must_use]
pub fn query(&self, q: &LogQuery) -> LogPage {
let ring = self.lock();
let oldest_seq = ring.entries.front().map_or(ring.next_seq, |e| e.seq);
let matcher = q.matcher();
let mut matched: Vec<BackendLogEntry> = Vec::new();
let mut total_matched = 0usize;
if let Some(since) = q.since_seq {
for e in ring.entries.range(ring.index_of(since)..) {
if matcher.matches(e) {
total_matched += 1;
if matched.len() < q.limit {
matched.push(e.clone());
}
}
}
} else {
for e in ring.entries.iter().rev() {
if !matcher.matches(e) {
continue;
}
total_matched += 1;
if matched.len() < q.limit {
matched.push(e.clone());
}
}
matched.reverse();
}
let truncated = total_matched > matched.len();
let gap = q.since_seq.is_some_and(|s| ring.evicted_since(s) > 0);
LogPage {
next_seq: page_next_seq(q.since_seq, truncated, &matched, ring.next_seq),
truncated,
total_matched,
entries: matched,
oldest_seq,
evicted: ring.evicted,
gap,
}
}
#[must_use]
pub fn range(
&self,
from: u64,
to: u64,
min_level: LogLevel,
limit: usize,
) -> (Vec<BackendLogEntry>, usize) {
let ring = self.lock();
let all: Vec<&BackendLogEntry> = ring
.entries
.range(ring.index_of(from)..)
.take_while(|e| e.seq < to)
.filter(|e| e.level >= min_level)
.collect();
let total = all.len();
let start = total.saturating_sub(limit);
(all[start..].iter().map(|e| (*e).clone()).collect(), total)
}
#[must_use]
pub fn digest(&self, recent: usize, top: usize) -> LogDigest {
let ring = self.lock();
let mut in_buffer = [0u64; 5];
let mut targets: HashMap<&str, u64> = HashMap::new();
let mut templates: HashMap<(LogLevel, String, String), TemplateStat> = HashMap::new();
let mut recent_problems: VecDeque<BackendLogEntry> = VecDeque::new();
let mut panics: Vec<BackendLogEntry> = Vec::new();
for e in &ring.entries {
in_buffer[e.level.index()] += 1;
*targets.entry(e.target.as_str()).or_default() += 1;
let key = (e.level, e.target.clone(), message_template(&e.message));
let stat = templates.entry(key).or_insert_with(|| TemplateStat {
count: 0,
first_ts_ms: e.ts_ms,
last_ts_ms: e.ts_ms,
last_seq: e.seq,
example: e.message.clone(),
});
stat.count += 1;
stat.last_ts_ms = e.ts_ms;
stat.last_seq = e.seq;
if e.level >= LogLevel::Warn {
recent_problems.push_back(e.clone());
if recent_problems.len() > recent {
recent_problems.pop_front();
}
}
if e.source == LogSource::Panic {
panics.push(e.clone());
}
}
let mut top_targets: Vec<(String, u64)> = targets
.into_iter()
.map(|(k, v)| (k.to_string(), v))
.collect();
top_targets.sort_by(|a, b| b.1.cmp(&a.1).then_with(|| a.0.cmp(&b.0)));
top_targets.truncate(top);
let mut repeated: Vec<RepeatedMessage> = templates
.into_iter()
.filter(|(_, s)| s.count > 1)
.map(|((level, target, template), s)| RepeatedMessage {
level,
target,
template,
count: s.count,
first_ts_ms: s.first_ts_ms,
last_ts_ms: s.last_ts_ms,
last_seq: s.last_seq,
example: s.example,
})
.collect();
repeated.sort_by(|a, b| {
b.level
.cmp(&a.level)
.then(b.count.cmp(&a.count))
.then_with(|| a.template.cmp(&b.template))
});
repeated.truncate(top);
LogDigest {
buffered: ring.entries.len(),
next_seq: ring.next_seq,
evicted: ring.evicted,
oldest_ts_ms: ring.entries.front().map(|e| e.ts_ms),
newest_ts_ms: ring.entries.back().map(|e| e.ts_ms),
lifetime_counts: level_map(&ring.totals),
buffered_counts: level_map(&in_buffer),
top_targets: top_targets
.into_iter()
.map(|(target, count)| TargetCount { target, count })
.collect(),
repeated,
recent_problems: recent_problems.into_iter().collect(),
panics,
}
}
pub async fn wait_for<F>(
&self,
from_seq: u64,
timeout: std::time::Duration,
pred: F,
) -> (Option<BackendLogEntry>, u64)
where
F: Fn(&BackendLogEntry) -> bool,
{
let deadline = tokio::time::Instant::now() + timeout;
let mut scanned_to = from_seq;
let mut missed = 0;
loop {
let notified = self.notify.notified();
tokio::pin!(notified);
{
let _scope = NotifyScope::enter();
notified.as_mut().enable();
}
{
let ring = self.lock();
missed += ring.evicted_since(scanned_to);
for e in ring.entries.range(ring.index_of(scanned_to)..) {
if pred(e) {
return (Some(e.clone()), missed);
}
}
scanned_to = scanned_to.max(ring.next_seq);
}
if tokio::time::timeout_at(deadline, PollInNotifyScope(notified.as_mut()))
.await
.is_err()
{
return (None, missed);
}
}
}
pub fn clear(&self) {
let mut ring = self.lock();
ring.entries.clear();
ring.bytes = 0;
ring.cleared_before = ring.next_seq;
}
}
struct TemplateStat {
count: u64,
first_ts_ms: u64,
last_ts_ms: u64,
last_seq: u64,
example: String,
}
fn level_map(counts: &[u64; 5]) -> BTreeMap<&'static str, u64> {
[
LogLevel::Trace,
LogLevel::Debug,
LogLevel::Info,
LogLevel::Warn,
LogLevel::Error,
]
.into_iter()
.map(|l| (l.as_str(), counts[l.index()]))
.collect()
}
#[must_use]
pub fn message_template(message: &str) -> String {
let mut out = String::with_capacity(message.len().min(256));
let mut chars = message.chars().peekable();
let mut last_was_placeholder = false;
while let Some(c) = chars.next() {
if c.is_ascii_digit() {
while let Some(&n) = chars.peek() {
if n.is_ascii_alphanumeric() || n == '.' || n == '-' || n == '_' || n == ':' {
chars.next();
} else {
break;
}
}
if !last_was_placeholder {
out.push('#');
}
last_was_placeholder = true;
} else if c == '"' {
for n in chars.by_ref() {
if n == '"' {
break;
}
}
out.push_str("\"…\"");
last_was_placeholder = true;
} else {
out.push(c);
last_was_placeholder = false;
}
if out.len() >= 240 {
out.push('…');
break;
}
}
out
}
#[derive(Debug, Clone)]
#[non_exhaustive]
pub struct LogQuery {
pub min_level: LogLevel,
pub targets: Vec<String>,
pub contains: Option<String>,
pub since_seq: Option<u64>,
pub since_ms: Option<u64>,
pub fields: Vec<(String, serde_json::Value)>,
pub limit: usize,
}
impl Default for LogQuery {
fn default() -> Self {
Self {
min_level: LogLevel::Trace,
targets: Vec::new(),
contains: None,
since_seq: None,
since_ms: None,
fields: Vec::new(),
limit: 100,
}
}
}
impl LogQuery {
fn matcher(&self) -> Matcher<'_> {
Matcher {
q: self,
needle: self.contains.as_ref().map(|s| s.to_lowercase()),
}
}
}
struct Matcher<'a> {
q: &'a LogQuery,
needle: Option<String>,
}
impl Matcher<'_> {
fn matches(&self, e: &BackendLogEntry) -> bool {
if e.level < self.q.min_level {
return false;
}
if let Some(ms) = self.q.since_ms
&& e.ts_ms < ms
{
return false;
}
if !self.q.targets.is_empty()
&& !self
.q
.targets
.iter()
.any(|t| e.target.starts_with(t.as_str()))
{
return false;
}
if !entry_fields_match(e, &self.q.fields) {
return false;
}
if let Some(needle) = &self.needle {
return entry_contains(e, needle);
}
true
}
}
#[must_use]
pub fn field_matches(entry: &BackendLogEntry, key: &str, expected: &serde_json::Value) -> bool {
fn text(v: &serde_json::Value) -> String {
match v {
serde_json::Value::String(s) => s.trim_matches('"').to_lowercase(),
other => other.to_string().to_lowercase(),
}
}
entry
.fields
.get(key)
.is_some_and(|actual| text(actual) == text(expected))
}
#[must_use]
pub fn entry_fields_match(entry: &BackendLogEntry, fields: &[(String, serde_json::Value)]) -> bool {
fields.iter().all(|(k, v)| field_matches(entry, k, v))
}
#[must_use]
pub fn entry_contains(e: &BackendLogEntry, needle: &str) -> bool {
if e.message.to_lowercase().contains(needle) || e.target.to_lowercase().contains(needle) {
return true;
}
if e.spans.iter().any(|s| s.to_lowercase().contains(needle)) {
return true;
}
e.fields.iter().any(|(k, v)| {
k.to_lowercase().contains(needle)
|| match v {
serde_json::Value::String(s) => s.to_lowercase().contains(needle),
other => other.to_string().to_lowercase().contains(needle),
}
})
}
#[must_use]
pub fn page_next_seq(
since_seq: Option<u64>,
truncated: bool,
entries: &[BackendLogEntry],
buffer_next_seq: u64,
) -> u64 {
match entries.last() {
Some(last) if since_seq.is_some() && truncated => last.seq + 1,
_ => buffer_next_seq,
}
}
#[derive(Debug, Clone, Serialize)]
#[non_exhaustive]
pub struct LogPage {
pub entries: Vec<BackendLogEntry>,
pub total_matched: usize,
pub truncated: bool,
pub next_seq: u64,
pub oldest_seq: u64,
pub evicted: u64,
pub gap: bool,
}
#[derive(Debug, Clone, Serialize)]
#[non_exhaustive]
pub struct LogDigest {
pub buffered: usize,
pub next_seq: u64,
pub evicted: u64,
pub oldest_ts_ms: Option<u64>,
pub newest_ts_ms: Option<u64>,
pub lifetime_counts: BTreeMap<&'static str, u64>,
pub buffered_counts: BTreeMap<&'static str, u64>,
pub top_targets: Vec<TargetCount>,
pub repeated: Vec<RepeatedMessage>,
pub recent_problems: Vec<BackendLogEntry>,
pub panics: Vec<BackendLogEntry>,
}
#[derive(Debug, Clone, Serialize)]
pub struct TargetCount {
pub target: String,
pub count: u64,
}
#[derive(Debug, Clone, Serialize)]
pub struct RepeatedMessage {
pub level: LogLevel,
pub target: String,
pub template: String,
pub count: u64,
pub first_ts_ms: u64,
pub last_ts_ms: u64,
pub last_seq: u64,
pub example: String,
}
static GLOBAL: OnceLock<Arc<LogBuffer>> = OnceLock::new();
static SOURCES: AtomicU8 = AtomicU8::new(0);
const SRC_TRACING: u8 = 1;
const SRC_LOG: u8 = 1 << 1;
const SRC_PANIC: u8 = 1 << 2;
const SRC_STRUCTURED_INSTALLED: u8 = 1 << 3;
#[must_use]
pub fn global() -> Arc<LogBuffer> {
GLOBAL
.get_or_init(|| {
let capacity = std::env::var("VICTAURI_LOG_CAPACITY")
.ok()
.and_then(|v| v.trim().parse::<usize>().ok())
.filter(|n| (1..=100_000).contains(n))
.unwrap_or(DEFAULT_CAPACITY);
Arc::new(LogBuffer::new(
capacity,
DEFAULT_MAX_BYTES.max(capacity * 512),
))
})
.clone()
}
#[derive(Debug, Clone, Copy, Serialize)]
#[allow(clippy::struct_excessive_bools)]
#[non_exhaustive]
pub struct ActiveSources {
pub tracing: bool,
pub log: bool,
pub panic_hook: bool,
pub stdout_capture: bool,
pub structured_installed: bool,
}
impl ActiveSources {
#[must_use]
pub const fn any_structured(self) -> bool {
self.tracing || self.log
}
}
#[must_use]
pub fn active_sources() -> ActiveSources {
let bits = SOURCES.load(Ordering::Relaxed);
ActiveSources {
tracing: bits & SRC_TRACING != 0,
log: bits & SRC_LOG != 0,
panic_hook: bits & SRC_PANIC != 0,
stdout_capture: console_capture_path().is_some(),
structured_installed: bits & SRC_STRUCTURED_INSTALLED != 0,
}
}
fn mark_source(bit: u8) {
SOURCES.fetch_or(bit, Ordering::Relaxed);
}
fn capture_disabled() -> bool {
if cfg!(not(debug_assertions)) {
return true;
}
std::env::var("VICTAURI_DISABLE").is_ok_and(|v| {
matches!(
v.trim().to_ascii_lowercase().as_str(),
"1" | "true" | "yes" | "on"
)
})
}
#[must_use]
pub fn is_internal_target(target: &str) -> bool {
static KEEP_INTERNAL: OnceLock<bool> = OnceLock::new();
let keep = *KEEP_INTERNAL.get_or_init(|| {
std::env::var("VICTAURI_LOG_INTERNAL").is_ok_and(|v| {
matches!(
v.trim().to_ascii_lowercase().as_str(),
"1" | "true" | "yes" | "on"
)
})
});
if keep {
return false;
}
target.starts_with("victauri_")
|| target == "victauri"
|| target == "rmcp"
|| target.starts_with("rmcp::")
}
#[must_use]
pub fn is_runtime_internal_target(target: &str) -> bool {
target == "tokio"
|| target.starts_with("tokio::")
|| target.starts_with("runtime::")
|| target.starts_with("runtime.")
}
#[must_use]
pub fn capture_level() -> LogLevel {
static LEVEL: OnceLock<LogLevel> = OnceLock::new();
*LEVEL.get_or_init(|| {
std::env::var("VICTAURI_LOG_LEVEL")
.ok()
.and_then(|v| LogLevel::parse(&v))
.unwrap_or(LogLevel::Debug)
})
}
fn now_ms() -> u64 {
std::time::SystemTime::now()
.duration_since(std::time::UNIX_EPOCH)
.map_or(0, |d| u64::try_from(d.as_millis()).unwrap_or(u64::MAX))
}
fn truncate_string(mut s: String, max: usize) -> String {
if s.len() > max {
let mut cut = max;
while cut > 0 && !s.is_char_boundary(cut) {
cut -= 1;
}
let extra = s.len() - cut;
s.truncate(cut);
let _ = write!(s, "…[+{extra} bytes]");
}
s
}
fn current_thread_name() -> Option<String> {
std::thread::current().name().map(str::to_string)
}
#[derive(Clone)]
#[cfg(debug_assertions)]
pub struct BackendLogLayer {
buffer: Arc<LogBuffer>,
}
#[cfg(debug_assertions)]
impl std::fmt::Debug for BackendLogLayer {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
f.debug_struct("BackendLogLayer").finish_non_exhaustive()
}
}
#[cfg(debug_assertions)]
impl BackendLogLayer {
#[must_use]
pub const fn with_buffer(buffer: Arc<LogBuffer>) -> Self {
Self { buffer }
}
}
#[cfg(not(debug_assertions))]
#[derive(Debug, Clone, Copy)]
pub struct BackendLogLayer {
_private: (),
}
#[cfg(not(debug_assertions))]
impl BackendLogLayer {
#[must_use]
pub fn with_buffer(_buffer: Arc<LogBuffer>) -> Self {
Self { _private: () }
}
}
#[cfg(not(debug_assertions))]
impl<S: Subscriber> Layer<S> for BackendLogLayer {}
#[must_use]
pub fn log_layer() -> Option<BackendLogLayer> {
if capture_disabled() {
return None;
}
mark_source(SRC_STRUCTURED_INSTALLED);
Some(BackendLogLayer::with_buffer(global()))
}
#[cfg(debug_assertions)]
struct SpanFields(String);
#[cfg(debug_assertions)]
impl<S> Layer<S> for BackendLogLayer
where
S: Subscriber + for<'a> LookupSpan<'a>,
{
fn max_level_hint(&self) -> Option<tracing::level_filters::LevelFilter> {
Some(capture_level().to_level_filter())
}
fn on_new_span(
&self,
attrs: &tracing::span::Attributes<'_>,
id: &tracing::span::Id,
ctx: Context<'_, S>,
) {
let mut v = SpanVisitor::default();
attrs.record(&mut v);
if let Some(span) = ctx.span(id) {
span.extensions_mut().insert(SpanFields(v.0));
}
}
fn on_record(
&self,
id: &tracing::span::Id,
values: &tracing::span::Record<'_>,
ctx: Context<'_, S>,
) {
if let Some(span) = ctx.span(id) {
let mut ext = span.extensions_mut();
let mut v = SpanVisitor(
ext.get_mut::<SpanFields>()
.map(|f| std::mem::take(&mut f.0))
.unwrap_or_default(),
);
values.record(&mut v);
if let Some(f) = ext.get_mut::<SpanFields>() {
f.0 = v.0;
} else {
ext.insert(SpanFields(v.0));
}
}
}
fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
mark_source(SRC_TRACING);
let meta = event.metadata();
if is_internal_target(meta.target())
|| is_runtime_internal_target(meta.target())
|| LogLevel::from_tracing(*meta.level()) < capture_level()
{
return;
}
let mut v = EventVisitor::default();
event.record(&mut v);
let mut target = meta.target().to_string();
let mut location = meta
.file()
.map(|f| format!("{f}:{}", meta.line().unwrap_or(0)));
if let Some(serde_json::Value::String(t)) = v.fields.remove("log.target") {
target = t;
}
let log_file = v.fields.remove("log.file");
let log_line = v.fields.remove("log.line");
v.fields.remove("log.module_path");
if let Some(serde_json::Value::String(f)) = log_file {
location = Some(format!(
"{f}:{}",
log_line.as_ref().map_or(0, |l| l.as_u64().unwrap_or(0))
));
}
let spans = ctx
.event_scope(event)
.map(|scope| {
scope
.from_root()
.map(|span| {
let ext = span.extensions();
match ext.get::<SpanFields>() {
Some(f) if !f.0.is_empty() => format!("{}{{{}}}", span.name(), f.0),
_ => span.name().to_string(),
}
})
.collect()
})
.unwrap_or_default();
self.buffer.push(BackendLogEntry {
seq: 0,
ts_ms: now_ms(),
level: LogLevel::from_tracing(*meta.level()),
target,
message: truncate_string(v.message, MAX_MESSAGE_BYTES),
fields: v.fields,
spans,
thread: current_thread_name(),
location,
source: LogSource::Tracing,
});
}
}
#[derive(Default)]
struct EventVisitor {
message: String,
fields: serde_json::Map<String, serde_json::Value>,
}
impl EventVisitor {
fn put(&mut self, field: &Field, value: serde_json::Value) {
if self.fields.len() < 64 {
self.fields.insert(field.name().to_string(), value);
}
}
}
impl Visit for EventVisitor {
fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
if field.name() == "message" {
self.message = debug_bounded(value, MAX_MESSAGE_BYTES);
} else {
self.put(
field,
serde_json::Value::String(debug_bounded(value, MAX_FIELD_BYTES)),
);
}
}
fn record_str(&mut self, field: &Field, value: &str) {
if field.name() == "message" {
value.clone_into(&mut self.message);
} else {
self.put(
field,
serde_json::Value::String(truncate_string(value.to_string(), MAX_FIELD_BYTES)),
);
}
}
fn record_i64(&mut self, field: &Field, value: i64) {
self.put(field, value.into());
}
fn record_u64(&mut self, field: &Field, value: u64) {
self.put(field, value.into());
}
fn record_f64(&mut self, field: &Field, value: f64) {
self.put(field, value.into());
}
fn record_bool(&mut self, field: &Field, value: bool) {
self.put(field, value.into());
}
fn record_error(&mut self, field: &Field, value: &(dyn std::error::Error + 'static)) {
let mut text = value.to_string();
let mut source = value.source();
let mut depth = 0;
while let Some(s) = source {
if depth >= 8 {
break;
}
let _ = write!(text, ": {s}");
source = s.source();
depth += 1;
}
self.put(
field,
serde_json::Value::String(truncate_string(text, MAX_FIELD_BYTES)),
);
}
}
#[derive(Default)]
struct SpanVisitor(String);
impl Visit for SpanVisitor {
fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
if self.0.len() > 512 {
return;
}
if !self.0.is_empty() {
self.0.push(' ');
}
let value = debug_bounded(value, MAX_FIELD_BYTES);
if field.name() == "message" {
self.0.push_str(&value);
} else {
let _ = write!(self.0, "{}={value}", field.name());
}
}
}
pub struct VictauriLogger {
inner: Option<Box<dyn log::Log>>,
buffer: Arc<LogBuffer>,
}
impl std::fmt::Debug for VictauriLogger {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
f.debug_struct("VictauriLogger")
.field("forwards", &self.inner.is_some())
.finish_non_exhaustive()
}
}
impl VictauriLogger {
#[must_use]
pub fn with_buffer(buffer: Arc<LogBuffer>, inner: Option<Box<dyn log::Log>>) -> Self {
Self { inner, buffer }
}
}
impl log::Log for VictauriLogger {
fn enabled(&self, metadata: &log::Metadata<'_>) -> bool {
match &self.inner {
Some(inner) => inner.enabled(metadata),
None => metadata.level() <= log::max_level(),
}
}
fn log(&self, record: &log::Record<'_>) {
mark_source(SRC_LOG);
if is_internal_target(record.target())
|| is_runtime_internal_target(record.target())
|| LogLevel::from_log(record.level()) < capture_level()
{
if let Some(inner) = &self.inner
&& inner.enabled(record.metadata())
{
inner.log(record);
}
return;
}
let mut fields = serde_json::Map::new();
if let Some(mp) = record.module_path()
&& mp != record.target()
{
fields.insert("module_path".into(), mp.into());
}
self.buffer.push(BackendLogEntry {
seq: 0,
ts_ms: now_ms(),
level: LogLevel::from_log(record.level()),
target: record.target().to_string(),
message: truncate_string(record.args().to_string(), MAX_MESSAGE_BYTES),
fields,
spans: Vec::new(),
thread: current_thread_name(),
location: record
.file()
.map(|f| format!("{f}:{}", record.line().unwrap_or(0))),
source: LogSource::Log,
});
if let Some(inner) = &self.inner
&& inner.enabled(record.metadata())
{
inner.log(record);
}
}
fn flush(&self) {
if let Some(inner) = &self.inner {
inner.flush();
}
}
}
#[must_use]
pub fn log_logger() -> Box<dyn log::Log> {
if capture_disabled() {
return Box::new(NullLogger);
}
mark_source(SRC_STRUCTURED_INSTALLED);
Box::new(VictauriLogger::with_buffer(global(), None))
}
#[must_use]
pub fn wrap_logger(inner: Box<dyn log::Log>) -> Box<dyn log::Log> {
if capture_disabled() {
return inner;
}
mark_source(SRC_STRUCTURED_INSTALLED);
Box::new(VictauriLogger::with_buffer(global(), Some(inner)))
}
struct NullLogger;
impl log::Log for NullLogger {
fn enabled(&self, _: &log::Metadata<'_>) -> bool {
false
}
fn log(&self, _: &log::Record<'_>) {}
fn flush(&self) {}
}
pub fn install_panic_hook() {
static INSTALLED: OnceLock<()> = OnceLock::new();
if capture_disabled() {
return;
}
INSTALLED.get_or_init(|| {
let buffer = global();
let previous = std::panic::take_hook();
std::panic::set_hook(Box::new(move |info| {
previous(info);
capture_panic(&buffer, info);
}));
mark_source(SRC_PANIC);
});
}
struct PendingBacktrace {
backtrace: std::backtrace::Backtrace,
resolved: OnceLock<String>,
}
fn pending_backtraces() -> &'static Mutex<HashMap<u32, Arc<PendingBacktrace>>> {
static PENDING: OnceLock<Mutex<HashMap<u32, Arc<PendingBacktrace>>>> = OnceLock::new();
PENDING.get_or_init(|| Mutex::new(HashMap::new()))
}
pub fn resolve_backtraces(value: &mut serde_json::Value) {
match value {
serde_json::Value::Object(map) => {
if let Some(id) = map
.get("backtrace_id")
.and_then(serde_json::Value::as_u64)
.and_then(|id| u32::try_from(id).ok())
{
let slot = pending_backtraces()
.lock()
.unwrap_or_else(std::sync::PoisonError::into_inner)
.get(&id)
.cloned();
if let Some(slot) = slot {
let text = slot.resolved.get_or_init(|| {
truncate_string(
trim_backtrace(&slot.backtrace.to_string()),
MAX_BACKTRACE_BYTES,
)
});
map.insert("backtrace".into(), text.clone().into());
}
map.remove("backtrace_id");
}
for v in map.values_mut() {
resolve_backtraces(v);
}
}
serde_json::Value::Array(items) => items.iter_mut().for_each(resolve_backtraces),
_ => {}
}
}
fn capture_panic(buffer: &LogBuffer, info: &std::panic::PanicHookInfo<'_>) {
static BACKTRACES_TAKEN: std::sync::atomic::AtomicU32 = std::sync::atomic::AtomicU32::new(0);
let payload = info.payload();
let message = payload
.downcast_ref::<&str>()
.map(|s| (*s).to_string())
.or_else(|| payload.downcast_ref::<String>().cloned())
.unwrap_or_else(|| "<non-string panic payload>".to_string());
let location = info
.location()
.map(|l| format!("{}:{}:{}", l.file(), l.line(), l.column()));
let mut fields = serde_json::Map::new();
let n = BACKTRACES_TAKEN.fetch_add(1, Ordering::Relaxed);
if n < MAX_PANIC_BACKTRACES {
let slot = Arc::new(PendingBacktrace {
backtrace: std::backtrace::Backtrace::force_capture(),
resolved: OnceLock::new(),
});
if let Ok(mut pending) = pending_backtraces().try_lock() {
pending.insert(n, slot);
fields.insert("backtrace_id".into(), n.into());
fields.insert("backtrace".into(), "(symbolised when read)".into());
}
} else {
fields.insert(
"backtrace".into(),
format!("omitted — only the first {MAX_PANIC_BACKTRACES} panics carry a backtrace")
.into(),
);
}
let thread = std::thread::current()
.name()
.map_or_else(|| "<unnamed>".to_string(), str::to_string);
let _ = buffer.try_push(BackendLogEntry {
seq: 0,
ts_ms: now_ms(),
level: LogLevel::Error,
target: "panic".to_string(),
message: truncate_string(message, MAX_MESSAGE_BYTES),
fields,
spans: Vec::new(),
thread: Some(thread),
location,
source: LogSource::Panic,
});
}
pub const MAX_PANIC_BACKTRACES: u32 = 20;
pub const MAX_BACKTRACE_FRAMES: usize = 40;
#[must_use]
pub fn trim_backtrace(raw: &str) -> String {
const MACHINERY: [&str; 9] = [
"std::backtrace",
"std::sys::backtrace",
"backtrace_rs",
"victauri_plugin::backend_logs",
"std::panicking",
"core::panicking",
"rust_begin_unwind",
"alloc::boxed::",
"__rustc",
];
let mut frames: Vec<Vec<&str>> = Vec::new();
for line in raw.lines() {
let t = line.trim_start();
let is_header = t
.split_once(':')
.is_some_and(|(n, _)| !n.is_empty() && n.chars().all(|c| c.is_ascii_digit()));
if is_header || frames.is_empty() {
frames.push(vec![line]);
} else if let Some(last) = frames.last_mut() {
last.push(line);
}
}
let first_real = frames
.iter()
.position(|f| !MACHINERY.iter().any(|m| f[0].contains(m)))
.unwrap_or(0);
let kept: Vec<String> = frames
.iter()
.skip(first_real)
.take(MAX_BACKTRACE_FRAMES)
.map(|f| f.join("\n"))
.collect();
let dropped = frames.len().saturating_sub(first_real + kept.len());
let mut out = kept.join("\n");
if dropped > 0 {
let _ = write!(out, "\n … {dropped} more frames");
}
out
}
pub const CONSOLE_CAPTURE_ENV: &str = "VICTAURI_CONSOLE_LOG";
#[must_use]
pub fn console_capture_path() -> Option<std::path::PathBuf> {
std::env::var_os(CONSOLE_CAPTURE_ENV)
.filter(|v| !v.is_empty())
.map(std::path::PathBuf::from)
}
#[derive(Debug, Clone, Serialize, serde::Deserialize)]
#[non_exhaustive]
pub struct ConsoleLine {
#[serde(default)]
pub offset: u64,
#[serde(rename = "t")]
pub ts_ms: u64,
#[serde(rename = "s")]
pub stream: String,
#[serde(rename = "l")]
pub text: String,
#[serde(default, skip_serializing_if = "Option::is_none")]
pub level: Option<LogLevel>,
#[serde(default, skip_serializing_if = "Vec::is_empty")]
pub tail: Vec<String>,
}
pub fn read_console_capture(
path: &std::path::Path,
from: Option<u64>,
tail_bytes: u64,
) -> std::io::Result<(Vec<ConsoleLine>, u64)> {
read_console_capture_window(path, from, tail_bytes, CONSOLE_READ_WINDOW)
.map(|(lines, next, _)| (lines, next))
}
pub const CONSOLE_READ_WINDOW: u64 = 16 * 1024 * 1024;
pub fn read_console_capture_window(
path: &std::path::Path,
from: Option<u64>,
tail_bytes: u64,
window: u64,
) -> std::io::Result<(Vec<ConsoleLine>, u64, bool)> {
use std::io::{Read, Seek, SeekFrom};
let mut file = std::fs::File::open(path)?;
let len = file.metadata()?.len();
let mut start = from.unwrap_or_else(|| len.saturating_sub(tail_bytes));
if start > len {
start = 0;
}
file.seek(SeekFrom::Start(start))?;
let mut buf = Vec::new();
file.take(window).read_to_end(&mut buf)?;
let more = start + (buf.len() as u64) < len;
let mut lines = Vec::new();
let mut offset = start;
let mut consumed = 0usize;
let mut first = from.is_none() && start > 0;
for chunk in buf.split_inclusive(|b| *b == b'\n') {
if !chunk.ends_with(b"\n") {
break; }
consumed += chunk.len();
let rec_offset = offset;
offset += chunk.len() as u64;
if first {
first = false;
continue;
}
if let Ok(mut line) = serde_json::from_slice::<ConsoleLine>(chunk) {
line.offset = rec_offset;
if line.level.is_none() {
line.level = infer_level(&line.text);
}
lines.push(line);
}
}
let more = more && consumed > 0;
Ok((lines, start + consumed as u64, more))
}
#[must_use]
pub fn infer_level(text: &str) -> Option<LogLevel> {
if text.contains("panicked at") || text.starts_with("error:") || text.starts_with("error[") {
return Some(LogLevel::Error);
}
if text.starts_with("warning:") {
return Some(LogLevel::Warn);
}
for token in text
.split(|c: char| c.is_whitespace() || c == '[' || c == ']')
.filter(|t| !t.is_empty())
.take(4)
{
match token {
"TRACE" => return Some(LogLevel::Trace),
"DEBUG" => return Some(LogLevel::Debug),
"INFO" => return Some(LogLevel::Info),
"WARN" | "WARNING" => return Some(LogLevel::Warn),
"ERROR" | "FATAL" => return Some(LogLevel::Error),
_ => {}
}
}
None
}
#[cfg(test)]
#[path = "backend_logs_tests.rs"]
mod tests;