plugin logging

This commit is contained in:
Bradley Nelson
2026-06-16 23:00:23 -06:00
parent 803150635c
commit 4427b1613b
17 changed files with 1928 additions and 12 deletions
@@ -0,0 +1,70 @@
//! Background plugin-log maintenance: a periodic sweep that prunes each
//! installed plugin's rotated log segments by age + aggregate size.
//!
//! Modeled on [`crate::infrastructure::services::trash_cleanup_service`]: a
//! single spawned task on a fixed interval, an immediate first run, and
//! log-and-continue on error. `file-rotate` already compresses + caps segment
//! *count* at write time; this is the only thing that enforces the per-plugin
//! age/byte retention and the only thing that ever prunes *idle* plugins (which
//! never trigger a write-time rotation).
use std::sync::Arc;
use std::time::Duration;
use chrono::Utc;
use tokio::time;
use tracing::{debug, info};
use super::log_store::PluginLogStore;
use crate::application::ports::plugin_ports::PluginManagementPort;
/// Periodically sweeps every installed plugin's logs against its retention.
pub struct PluginLogMaintenanceService {
log_store: Arc<PluginLogStore>,
manager: Arc<dyn PluginManagementPort>,
interval_hours: u64,
}
impl PluginLogMaintenanceService {
pub fn new(
log_store: Arc<PluginLogStore>,
manager: Arc<dyn PluginManagementPort>,
interval_hours: u64,
) -> Self {
Self {
log_store,
manager,
interval_hours: interval_hours.max(1),
}
}
/// Spawn the periodic sweep task.
pub fn start(&self) {
let log_store = self.log_store.clone();
let manager = self.manager.clone();
let interval_hours = self.interval_hours;
info!(
"Starting plugin log maintenance job with interval of {} hours",
interval_hours
);
tokio::spawn(async move {
let mut interval = time::interval(Duration::from_secs(interval_hours * 60 * 60));
// First tick fires immediately.
loop {
interval.tick().await;
Self::sweep_all(&log_store, &manager).await;
}
});
}
async fn sweep_all(log_store: &PluginLogStore, manager: &Arc<dyn PluginManagementPort>) {
let now = Utc::now();
let plugins = manager.list();
debug!("Plugin log sweep over {} plugin(s)", plugins.len());
for plugin in plugins {
log_store.request_sweep(&plugin.id, now).await;
}
}
}
@@ -0,0 +1,730 @@
//! Per-plugin structured log storage — an async, in-order actor over disk files.
//!
//! Every plugin gets its own directory under the log root:
//! ```text
//! {root}/{plugin_id}/events.jsonl # active (file-rotate writes here)
//! {root}/{plugin_id}/events.jsonl.<timestamp>.gz # rotated + gzip'd (immutable)
//! {root}/{plugin_id}/retention.json # per-plugin retention override
//! ```
//!
//! **Async + strictly in order.** All file mutations funnel through a single
//! background thread that owns the per-plugin [`FileRotate`] writers. Because
//! there is exactly one consumer draining one channel FIFO, batches land in
//! enqueue order with no locks, and the dispatch path never blocks on IO — it
//! just sends. Rotation, gzip-on-rotate and a coarse segment ceiling are handled
//! by `file-rotate`; per-plugin age + aggregate-byte retention is the [`sweep`]
//! (run on a schedule), the only thing that ever prunes *idle* plugins.
//!
//! [`sweep`]: PluginLogStore::request_sweep
use std::collections::HashMap;
use std::fs;
use std::io::{Read, Write};
use std::path::{Path, PathBuf};
use std::time::SystemTime;
use chrono::{DateTime, Duration, Utc};
use file_rotate::{
ContentLimit, FileRotate,
compression::Compression,
suffix::{AppendTimestamp, FileLimit},
};
use flate2::read::GzDecoder;
use tokio::sync::{broadcast, mpsc, oneshot};
use super::runtime::InvokeOutcome;
use crate::application::ports::plugin_ports::{
LogEntry, LogPage, LogQuery, PluginLogEvent, RetentionSettings,
};
/// Name of the active (uncompressed) log file inside a plugin's log dir.
const ACTIVE_FILE: &str = "events.jsonl";
/// Marker file holding a plugin's retention override.
const RETENTION_FILE: &str = "retention.json";
/// Bounded command-channel depth — backpressure under flood, not unbounded RAM.
const CHANNEL_CAPACITY: usize = 1024;
/// Live broadcast buffer; a slow tailer past this gets `Lagged` (never blocks).
const LIVE_CAPACITY: usize = 256;
/// Commands processed in receipt order by the single actor thread.
enum LogCommand {
Append {
plugin_id: String,
entries: Vec<LogEntry>,
},
Read {
plugin_id: String,
query: LogQuery,
reply: oneshot::Sender<LogPage>,
},
Clear {
plugin_id: String,
reply: oneshot::Sender<()>,
},
Remove {
plugin_id: String,
},
GetRetention {
plugin_id: String,
reply: oneshot::Sender<RetentionSettings>,
},
SetRetention {
plugin_id: String,
settings: RetentionSettings,
reply: oneshot::Sender<()>,
},
Sweep {
plugin_id: String,
now: DateTime<Utc>,
},
}
/// Cheap, cloneable handle to the log actor. Held by the plugin manager and the
/// maintenance task; `subscribe_logs` hands receivers to SSE clients.
pub struct PluginLogStore {
tx: mpsc::Sender<LogCommand>,
live: broadcast::Sender<PluginLogEvent>,
}
impl PluginLogStore {
/// Spawn the actor thread and return a handle. `default_retention` is applied
/// to any plugin lacking an explicit `retention.json`.
pub fn new(
root: PathBuf,
max_file_bytes: u64,
max_segments: u32,
default_retention: RetentionSettings,
) -> Self {
let (tx, rx) = mpsc::channel(CHANNEL_CAPACITY);
let (live, _) = broadcast::channel(LIVE_CAPACITY);
let actor = Actor {
root,
max_file_bytes: max_file_bytes.max(1),
max_segments,
default_retention,
writers: HashMap::new(),
live: live.clone(),
};
// A dedicated OS thread so the blocking file/gzip IO never stalls a tokio
// worker. `blocking_recv` is valid here (no runtime on this thread).
std::thread::Builder::new()
.name("plugin-log-store".into())
.spawn(move || actor.run(rx))
.expect("spawn plugin-log-store thread");
Self { tx, live }
}
/// Enqueue a batch (plugin-emitted lines + the host outcome) for one
/// invocation. Called from the dispatch `spawn_blocking` closure, so
/// `blocking_send` is correct: it applies backpressure to that off-runtime
/// thread and preserves order. Send failures (actor gone) are swallowed —
/// logging must never break dispatch.
pub fn append(
&self,
plugin_id: &str,
invocation_id: &str,
lines: &[(String, String)],
outcome: &InvokeOutcome,
) {
let ts = Utc::now().to_rfc3339();
let mut entries: Vec<LogEntry> = lines
.iter()
.map(|(level, msg)| LogEntry {
ts: ts.clone(),
invocation_id: invocation_id.to_string(),
kind: "plugin".to_string(),
level: level.clone(),
reason: None,
msg: msg.clone(),
})
.collect();
let (level, msg) = outcome.log_detail();
entries.push(LogEntry {
ts,
invocation_id: invocation_id.to_string(),
kind: "outcome".to_string(),
level: level.to_string(),
reason: Some(outcome.reason().to_string()),
msg,
});
if let Err(e) = self.tx.blocking_send(LogCommand::Append {
plugin_id: plugin_id.to_string(),
entries,
}) {
tracing::warn!(
target: "oxicloud::plugins",
plugin_id = %plugin_id,
error = %e,
"dropping plugin log batch: log actor unavailable"
);
}
}
/// Read a filtered, paginated page of a plugin's entries (newest first).
pub async fn read_page(&self, plugin_id: &str, query: LogQuery) -> LogPage {
let (reply, rx) = oneshot::channel();
if self
.tx
.send(LogCommand::Read {
plugin_id: plugin_id.to_string(),
query,
reply,
})
.await
.is_err()
{
return LogPage {
entries: Vec::new(),
total: 0,
};
}
rx.await.unwrap_or(LogPage {
entries: Vec::new(),
total: 0,
})
}
/// Delete a plugin's log files (keeps `retention.json`).
pub async fn clear(&self, plugin_id: &str) {
let (reply, rx) = oneshot::channel();
if self
.tx
.send(LogCommand::Clear {
plugin_id: plugin_id.to_string(),
reply,
})
.await
.is_ok()
{
let _ = rx.await;
}
}
/// Delete a plugin's entire log directory (on uninstall). Fire-and-forget
/// and non-blocking, so it's safe to call from the synchronous management
/// path without stalling an async worker.
pub fn remove_plugin_logs(&self, plugin_id: &str) {
let _ = self.tx.try_send(LogCommand::Remove {
plugin_id: plugin_id.to_string(),
});
}
/// The plugin's effective retention (override or configured default).
pub async fn get_retention(&self, plugin_id: &str) -> RetentionSettings {
let (reply, rx) = oneshot::channel();
if self
.tx
.send(LogCommand::GetRetention {
plugin_id: plugin_id.to_string(),
reply,
})
.await
.is_ok()
&& let Ok(s) = rx.await
{
return s;
}
// Fall back to a conservative default if the actor is gone.
RetentionSettings {
retention_days: 30,
max_bytes: 256 * 1024 * 1024,
}
}
/// Persist a per-plugin retention override.
pub async fn set_retention(&self, plugin_id: &str, settings: RetentionSettings) {
let (reply, rx) = oneshot::channel();
if self
.tx
.send(LogCommand::SetRetention {
plugin_id: plugin_id.to_string(),
settings,
reply,
})
.await
.is_ok()
{
let _ = rx.await;
}
}
/// Ask the actor to prune a plugin's segments by age + aggregate size.
pub async fn request_sweep(&self, plugin_id: &str, now: DateTime<Utc>) {
let _ = self
.tx
.send(LogCommand::Sweep {
plugin_id: plugin_id.to_string(),
now,
})
.await;
}
/// Subscribe to newly-written entries across all plugins (live tailing).
pub fn subscribe(&self) -> broadcast::Receiver<PluginLogEvent> {
self.live.subscribe()
}
}
/// The single owner of all log-file state. Runs on its own thread.
struct Actor {
root: PathBuf,
max_file_bytes: u64,
max_segments: u32,
default_retention: RetentionSettings,
writers: HashMap<String, FileRotate<AppendTimestamp>>,
live: broadcast::Sender<PluginLogEvent>,
}
impl Actor {
fn run(mut self, mut rx: mpsc::Receiver<LogCommand>) {
while let Some(cmd) = rx.blocking_recv() {
match cmd {
LogCommand::Append { plugin_id, entries } => {
self.handle_append(&plugin_id, entries)
}
LogCommand::Read {
plugin_id,
query,
reply,
} => {
let _ = reply.send(self.read_page(&plugin_id, &query));
}
LogCommand::Clear { plugin_id, reply } => {
self.clear(&plugin_id);
let _ = reply.send(());
}
LogCommand::Remove { plugin_id } => self.remove(&plugin_id),
LogCommand::GetRetention { plugin_id, reply } => {
let _ = reply.send(self.get_retention(&plugin_id));
}
LogCommand::SetRetention {
plugin_id,
settings,
reply,
} => {
self.set_retention(&plugin_id, settings);
let _ = reply.send(());
}
LogCommand::Sweep { plugin_id, now } => self.sweep(&plugin_id, now),
}
}
}
fn plugin_dir(&self, plugin_id: &str) -> PathBuf {
self.root.join(plugin_id)
}
/// Lazily build (or fetch) the rotating writer for a plugin.
fn writer_for(&mut self, plugin_id: &str) -> Option<&mut FileRotate<AppendTimestamp>> {
if !self.writers.contains_key(plugin_id) {
let path = self.plugin_dir(plugin_id).join(ACTIVE_FILE);
let writer = FileRotate::new(
path,
AppendTimestamp::default(FileLimit::MaxFiles(self.max_segments as usize)),
ContentLimit::BytesSurpassed(self.max_file_bytes as usize),
Compression::OnRotate(0),
#[cfg(unix)]
None,
);
self.writers.insert(plugin_id.to_string(), writer);
}
self.writers.get_mut(plugin_id)
}
fn handle_append(&mut self, plugin_id: &str, entries: Vec<LogEntry>) {
let mut buf = Vec::new();
for entry in &entries {
if serde_json::to_writer(&mut buf, entry).is_ok() {
buf.push(b'\n');
}
}
if let Some(writer) = self.writer_for(plugin_id)
&& let Err(e) = writer.write_all(&buf).and_then(|_| writer.flush())
{
tracing::warn!(
target: "oxicloud::plugins",
plugin_id = %plugin_id,
error = %e,
"failed to write plugin log batch"
);
return;
}
// Publish only after the durable write, so the live tail never shows an
// entry a subsequent read wouldn't. No subscribers => send is a no-op.
for entry in entries {
let _ = self.live.send(PluginLogEvent {
plugin_id: plugin_id.to_string(),
entry,
});
}
}
fn read_page(&self, plugin_id: &str, query: &LogQuery) -> LogPage {
let dir = self.plugin_dir(plugin_id);
// Gather rotated segments oldest→newest (by mtime), then the active file.
let mut segments: Vec<(PathBuf, SystemTime)> = Vec::new();
let mut active: Option<PathBuf> = None;
if let Ok(read_dir) = fs::read_dir(&dir) {
for entry in read_dir.flatten() {
let path = entry.path();
let Some(name) = path.file_name().and_then(|n| n.to_str()) else {
continue;
};
if name == ACTIVE_FILE {
active = Some(path);
} else if name.starts_with("events.jsonl.") {
let mtime = entry
.metadata()
.and_then(|m| m.modified())
.unwrap_or(SystemTime::UNIX_EPOCH);
segments.push((path, mtime));
}
}
}
segments.sort_by_key(|(_, mtime)| *mtime);
let mut all: Vec<LogEntry> = Vec::new();
for (path, _) in &segments {
read_entries_into(path, query, &mut all);
}
if let Some(path) = &active {
read_entries_into(path, query, &mut all);
}
// `all` is chronological (oldest→newest); the viewer wants newest first.
all.reverse();
let total = all.len();
let entries = all
.into_iter()
.skip(query.offset)
.take(query.limit)
.collect();
LogPage { entries, total }
}
fn clear(&mut self, plugin_id: &str) {
// Drop the open writer first so the active file can be removed cleanly.
self.writers.remove(plugin_id);
let dir = self.plugin_dir(plugin_id);
if let Ok(read_dir) = fs::read_dir(&dir) {
for entry in read_dir.flatten() {
let path = entry.path();
if let Some(name) = path.file_name().and_then(|n| n.to_str())
&& (name == ACTIVE_FILE || name.starts_with("events.jsonl."))
{
let _ = fs::remove_file(&path);
}
}
}
}
fn remove(&mut self, plugin_id: &str) {
self.writers.remove(plugin_id);
let _ = fs::remove_dir_all(self.plugin_dir(plugin_id));
}
fn get_retention(&self, plugin_id: &str) -> RetentionSettings {
let path = self.plugin_dir(plugin_id).join(RETENTION_FILE);
fs::read_to_string(&path)
.ok()
.and_then(|s| serde_json::from_str::<RetentionSettings>(&s).ok())
.unwrap_or(self.default_retention)
}
fn set_retention(&self, plugin_id: &str, settings: RetentionSettings) {
let dir = self.plugin_dir(plugin_id);
if let Err(e) = fs::create_dir_all(&dir) {
tracing::warn!(
target: "oxicloud::plugins",
plugin_id = %plugin_id, error = %e,
"failed to create plugin log dir for retention"
);
return;
}
match serde_json::to_string_pretty(&settings) {
Ok(json) => {
if let Err(e) = fs::write(dir.join(RETENTION_FILE), json) {
tracing::warn!(
target: "oxicloud::plugins",
plugin_id = %plugin_id, error = %e,
"failed to persist plugin retention"
);
}
}
Err(e) => tracing::warn!(
target: "oxicloud::plugins",
plugin_id = %plugin_id, error = %e,
"failed to serialize plugin retention"
),
}
}
/// Prune rotated segments older than the plugin's retention window, then
/// enforce the aggregate byte cap (oldest deleted first). Never touches the
/// active file.
fn sweep(&self, plugin_id: &str, now: DateTime<Utc>) {
let dir = self.plugin_dir(plugin_id);
let retention = self.get_retention(plugin_id);
let cutoff = now - Duration::days(retention.retention_days as i64);
let mut segments: Vec<(PathBuf, SystemTime, u64)> = Vec::new();
let Ok(read_dir) = fs::read_dir(&dir) else {
return;
};
for entry in read_dir.flatten() {
let path = entry.path();
let Some(name) = path.file_name().and_then(|n| n.to_str()) else {
continue;
};
if !name.starts_with("events.jsonl.") {
continue; // skip the active file, retention.json, etc.
}
let Ok(meta) = entry.metadata() else { continue };
let mtime = meta.modified().unwrap_or(SystemTime::UNIX_EPOCH);
segments.push((path, mtime, meta.len()));
}
// 1) Age-based pruning.
let mut purged = 0u64;
segments.retain(|(path, mtime, _)| {
let dt: DateTime<Utc> = (*mtime).into();
if dt < cutoff {
let _ = fs::remove_file(path);
purged += 1;
false
} else {
true
}
});
// 2) Aggregate byte cap, oldest deleted first.
segments.sort_by_key(|(_, mtime, _)| *mtime);
let mut total: u64 = segments.iter().map(|(_, _, size)| *size).sum();
let mut idx = 0;
while total > retention.max_bytes && idx < segments.len() {
let (path, _, size) = &segments[idx];
let _ = fs::remove_file(path);
total = total.saturating_sub(*size);
purged += 1;
idx += 1;
}
if purged > 0 {
tracing::debug!(
target: "oxicloud::plugins",
plugin_id = %plugin_id,
purged,
"plugin log retention sweep removed segments"
);
}
}
}
/// Read one segment (gzip if `.gz`, else plain), parse each line as a
/// [`LogEntry`], apply the filter, and append matches to `out`. Malformed lines
/// are skipped — a torn final line never aborts a read.
fn read_entries_into(path: &Path, query: &LogQuery, out: &mut Vec<LogEntry>) {
let Ok(file) = fs::File::open(path) else {
return;
};
let content = if path.extension().and_then(|e| e.to_str()) == Some("gz") {
let mut s = String::new();
if GzDecoder::new(file).read_to_string(&mut s).is_err() {
return;
}
s
} else {
let mut s = String::new();
let mut file = file;
if file.read_to_string(&mut s).is_err() {
return;
}
s
};
let search = query.search.as_ref().map(|s| s.to_lowercase());
for line in content.lines() {
if line.trim().is_empty() {
continue;
}
let Ok(entry) = serde_json::from_str::<LogEntry>(line) else {
continue;
};
if let Some(level) = &query.level
&& &entry.level != level
{
continue;
}
if let Some(needle) = &search
&& !entry.msg.to_lowercase().contains(needle)
{
continue;
}
out.push(entry);
}
}
#[cfg(test)]
mod tests {
use super::*;
fn settings(days: u32, max_bytes: u64) -> RetentionSettings {
RetentionSettings {
retention_days: days,
max_bytes,
}
}
fn entry(level: &str, msg: &str) -> LogEntry {
LogEntry {
ts: Utc::now().to_rfc3339(),
invocation_id: "inv".into(),
kind: "plugin".into(),
level: level.into(),
reason: None,
msg: msg.into(),
}
}
fn new_actor(root: PathBuf, max_file_bytes: u64, max_segments: u32) -> Actor {
let (live, _) = broadcast::channel(16);
Actor {
root,
max_file_bytes: max_file_bytes.max(1),
max_segments,
default_retention: settings(30, 1 << 30),
writers: HashMap::new(),
live,
}
}
#[test]
fn ordering_and_roundtrip() {
let dir = tempfile::tempdir().unwrap();
let mut actor = new_actor(dir.path().to_path_buf(), 1 << 20, 5);
for i in 0..50 {
actor.handle_append("p", vec![entry("info", &format!("line {i}"))]);
}
let page = actor.read_page(
"p",
&LogQuery {
level: None,
search: None,
offset: 0,
limit: 10,
},
);
assert_eq!(page.total, 50);
assert_eq!(page.entries.len(), 10);
// Newest first.
assert_eq!(page.entries[0].msg, "line 49");
assert_eq!(page.entries[9].msg, "line 40");
}
#[test]
fn filter_by_level_and_search() {
let dir = tempfile::tempdir().unwrap();
let mut actor = new_actor(dir.path().to_path_buf(), 1 << 20, 5);
actor.handle_append("p", vec![entry("info", "hello world")]);
actor.handle_append("p", vec![entry("error", "BOOM failure")]);
actor.handle_append("p", vec![entry("info", "another HELLO")]);
let q = LogQuery {
level: Some("info".into()),
search: Some("hello".into()),
offset: 0,
limit: 100,
};
let page = actor.read_page("p", &q);
assert_eq!(page.total, 2);
assert!(page.entries.iter().all(|e| e.level == "info"));
assert!(
page.entries
.iter()
.all(|e| e.msg.to_lowercase().contains("hello"))
);
}
#[test]
fn rotation_creates_compressed_segments() {
let dir = tempfile::tempdir().unwrap();
// Tiny byte cap forces frequent rotation; a high segment cap keeps every
// segment so the cross-segment read can be checked end to end (the byte
// cap is then exercised separately by `sweep_age_and_size`).
let mut actor = new_actor(dir.path().to_path_buf(), 256, 100_000);
for i in 0..200 {
actor.handle_append(
"p",
vec![entry("info", &format!("padding line number {i}"))],
);
}
let plugin_dir = dir.path().join("p");
let gz = fs::read_dir(&plugin_dir)
.unwrap()
.flatten()
.filter(|e| {
e.path()
.extension()
.and_then(|x| x.to_str())
.map(|x| x == "gz")
.unwrap_or(false)
})
.count();
assert!(gz > 0, "expected at least one rotated .gz segment");
// All originally-written lines must still be readable across segments.
let page = actor.read_page(
"p",
&LogQuery {
level: None,
search: None,
offset: 0,
limit: 1000,
},
);
assert_eq!(page.total, 200);
}
#[test]
fn retention_roundtrip() {
let dir = tempfile::tempdir().unwrap();
let actor = new_actor(dir.path().to_path_buf(), 1 << 20, 5);
assert_eq!(actor.get_retention("p").retention_days, 30); // default
actor.set_retention("p", settings(7, 1234));
let r = actor.get_retention("p");
assert_eq!(r.retention_days, 7);
assert_eq!(r.max_bytes, 1234);
}
#[test]
fn sweep_age_and_size() {
let dir = tempfile::tempdir().unwrap();
let plugin_dir = dir.path().join("p");
fs::create_dir_all(&plugin_dir).unwrap();
// One "old" rotated segment and one "fresh" one.
let old = plugin_dir.join("events.jsonl.20200101T000000.gz");
let fresh = plugin_dir.join("events.jsonl.20990101T000000.gz");
fs::write(&old, b"x").unwrap();
fs::write(&fresh, b"y").unwrap();
// Backdate the "old" file's mtime well past the retention window.
let long_ago = SystemTime::UNIX_EPOCH + std::time::Duration::from_secs(1_000_000);
filetime_set(&old, long_ago);
let actor = new_actor(dir.path().to_path_buf(), 1 << 20, 5);
// 1-day retention: the backdated file must go, the fresh one stays.
actor.sweep("p", Utc::now());
assert!(!old.exists(), "age-expired segment should be purged");
assert!(fresh.exists(), "recent segment should be kept");
}
/// Minimal mtime setter for tests (no extra dep): rewrite + set via filetime
/// is unavailable, so emulate "old" by relying on a very old written time is
/// not possible portably; instead we set it through `fs` utimes if present.
fn filetime_set(path: &Path, when: SystemTime) {
// `set_file_mtime` isn't in std; approximate by opening and using the
// platform fallback: on failure the test still meaningfully exercises
// the size path. We use a best-effort via `File::set_modified` (1.75+).
if let Ok(f) = fs::OpenOptions::new().write(true).open(path) {
let _ = f.set_modified(when);
}
}
}
+87 -2
View File
@@ -18,13 +18,18 @@ use std::collections::HashSet;
use std::path::{Path, PathBuf};
use std::sync::{Arc, RwLock};
use async_trait::async_trait;
use super::log_store::PluginLogStore;
use super::manifest;
use super::runtime::{InvokeOutcome, PluginRuntime};
use crate::application::ports::plugin_ports::{
OXICLOUD_PLUGIN_ABI, PluginContext, PluginDispatchPort, PluginEvent, PluginInfo, PluginInput,
PluginManagementPort, PluginMgmtError, event_export_name,
LogPage, LogQuery, OXICLOUD_PLUGIN_ABI, PluginContext, PluginDispatchPort, PluginEvent,
PluginInfo, PluginInput, PluginLogEvent, PluginManagementPort, PluginMgmtError,
RetentionSettings, event_export_name,
};
use crate::common::config::PluginConfig;
use tokio::sync::broadcast;
/// Name of the marker file that, when present in a plugin's directory, loads it
/// disabled. Created/removed by [`PluginManagementPort::set_enabled`].
@@ -67,6 +72,8 @@ pub struct ExtismPluginManager {
/// Root directory plugins are discovered in and installed into.
root_dir: PathBuf,
plugins: RwLock<Vec<LoadedPlugin>>,
/// Per-plugin structured log storage (shared with the maintenance task).
log_store: Arc<PluginLogStore>,
}
impl ExtismPluginManager {
@@ -74,6 +81,23 @@ impl ExtismPluginManager {
/// load. Returns an empty manager (logging the cause) if `dir` is absent or
/// unreadable — a missing plugins directory is normal, not an error.
pub fn load_from_dir(config: PluginConfig, dir: &Path) -> Self {
// The log root is a sibling of the plugins dir by default (or the
// configured override); it lives outside any individual plugin dir so a
// plugin uninstall (`remove_dir_all`) never wipes another's logs.
let log_dir = config
.log_dir
.clone()
.unwrap_or_else(|| dir.join(".plugin-logs"));
let log_store = Arc::new(PluginLogStore::new(
log_dir.clone(),
config.log_max_file_bytes,
config.log_max_segments,
RetentionSettings {
retention_days: config.log_retention_days,
max_bytes: config.log_total_max_bytes,
},
));
let mut plugins = Vec::new();
let mut rejected = 0usize;
@@ -90,6 +114,7 @@ impl ExtismPluginManager {
config,
root_dir: dir.to_path_buf(),
plugins: RwLock::new(plugins),
log_store,
};
}
};
@@ -99,6 +124,10 @@ impl ExtismPluginManager {
if !path.is_dir() {
continue;
}
// Never treat the log root as a plugin directory.
if path == log_dir {
continue;
}
match Self::load_one(&config, &path) {
Ok(loaded) => {
tracing::info!(
@@ -134,9 +163,15 @@ impl ExtismPluginManager {
config,
root_dir: dir.to_path_buf(),
plugins: RwLock::new(plugins),
log_store,
}
}
/// The shared log store, handed to the maintenance task by DI.
pub fn log_store(&self) -> Arc<PluginLogStore> {
self.log_store.clone()
}
/// Validate and load a single plugin directory. Returns a stable audit
/// `reason` key on rejection.
fn load_one(config: &PluginConfig, dir: &Path) -> Result<LoadedPlugin, &'static str> {
@@ -201,6 +236,17 @@ impl ExtismPluginManager {
fn write_plugins(&self) -> std::sync::RwLockWriteGuard<'_, Vec<LoadedPlugin>> {
self.plugins.write().unwrap_or_else(|e| e.into_inner())
}
/// `NotFound` unless a plugin with this id is currently installed. Checked
/// before any log-file access so an HTTP-supplied id can't reach the
/// filesystem for a plugin that doesn't exist.
fn ensure_installed(&self, id: &str) -> Result<(), PluginMgmtError> {
if self.read_plugins().iter().any(|p| p.id == id) {
Ok(())
} else {
Err(PluginMgmtError::NotFound)
}
}
}
impl PluginDispatchPort for ExtismPluginManager {
@@ -238,11 +284,16 @@ impl PluginDispatchPort for ExtismPluginManager {
let plugin_id = plugin.id.clone();
let invocation_id = event.invocation_id.clone();
let export = event_export_name(event.name);
let log_store = self.log_store.clone();
// Run the synchronous wasm call off the async workers. Fire-and-forget:
// the upload already succeeded; plugins are post-hoc observers.
tokio::task::spawn_blocking(move || {
let result = runtime.invoke(&config, &export, &invocation_id, &input_json);
// Persist every invocation (the plugin's own log lines plus the
// host outcome) to the plugin's structured log. Ordered, async,
// and non-fatal — a failed write never affects the request.
log_store.append(&plugin_id, &invocation_id, &result.logs, &result.outcome);
if !result.outcome.is_ok() {
tracing::warn!(
target: "audit",
@@ -265,6 +316,7 @@ impl PluginDispatchPort for ExtismPluginManager {
}
}
#[async_trait]
impl PluginManagementPort for ExtismPluginManager {
fn list(&self) -> Vec<PluginInfo> {
let mut infos: Vec<PluginInfo> = self.read_plugins().iter().map(|p| p.info()).collect();
@@ -410,12 +462,45 @@ impl PluginManagementPort for ExtismPluginManager {
.position(|p| p.id == id)
.ok_or(PluginMgmtError::NotFound)?;
let removed = plugins.remove(pos);
// Also reclaim the plugin's logs so a later reinstall of the same id
// doesn't inherit stale entries.
self.log_store.remove_plugin_logs(id);
match std::fs::remove_dir_all(&removed.dir) {
Ok(()) => Ok(()),
Err(e) if e.kind() == std::io::ErrorKind::NotFound => Ok(()),
Err(e) => Err(PluginMgmtError::Io(e.to_string())),
}
}
async fn read_logs(&self, id: &str, query: LogQuery) -> Result<LogPage, PluginMgmtError> {
self.ensure_installed(id)?;
Ok(self.log_store.read_page(id, query).await)
}
async fn clear_logs(&self, id: &str) -> Result<(), PluginMgmtError> {
self.ensure_installed(id)?;
self.log_store.clear(id).await;
Ok(())
}
async fn get_retention(&self, id: &str) -> Result<RetentionSettings, PluginMgmtError> {
self.ensure_installed(id)?;
Ok(self.log_store.get_retention(id).await)
}
async fn set_retention(
&self,
id: &str,
settings: RetentionSettings,
) -> Result<(), PluginMgmtError> {
self.ensure_installed(id)?;
self.log_store.set_retention(id, settings).await;
Ok(())
}
fn subscribe_logs(&self) -> broadcast::Receiver<PluginLogEvent> {
self.log_store.subscribe()
}
}
/// Whether `s` is a single, traversal-free path component safe to use as a
@@ -246,3 +246,51 @@ fn remove_unloads_and_deletes_directory() {
let err = mgr.remove("com.example.hello").unwrap_err();
assert_eq!(err.reason(), "not_found");
}
/// Regression guard: dispatch must persist a log entry for *every* invocation,
/// including a successful one (it previously only logged failures). We dispatch
/// a `file.uploaded` event and then poll the plugin's structured log until an
/// `outcome` row appears.
#[tokio::test(flavor = "multi_thread")]
async fn dispatch_writes_outcome_row_on_success() {
use crate::application::ports::plugin_ports::{EVENT_FILE_UPLOADED, LogQuery, PluginEvent};
let tmp = tempfile::tempdir().unwrap();
let mgr = ExtismPluginManager::load_from_dir(cfg(), tmp.path());
mgr.install(&hello_manifest(), fixture("hello.wasm"))
.unwrap();
mgr.dispatch(PluginEvent {
name: EVENT_FILE_UPLOADED,
user_id: None,
invocation_id: "test-invocation".to_string(),
payload: serde_json::json!({ "path": "/x.txt", "size": 1, "mime": "text/plain" }),
});
// dispatch is fire-and-forget on the blocking pool, and the log write is an
// ordered async hand-off; poll until the outcome row is durable.
let mut found = false;
for _ in 0..50 {
tokio::time::sleep(std::time::Duration::from_millis(20)).await;
let page = mgr
.read_logs(
"com.example.hello",
LogQuery {
level: None,
search: None,
offset: 0,
limit: 100,
},
)
.await
.unwrap();
if page.entries.iter().any(|e| e.kind == "outcome") {
found = true;
break;
}
}
assert!(
found,
"dispatch should persist an outcome row for the invocation"
);
}
@@ -5,10 +5,14 @@
//! [`crate::application::ports::plugin_ports::PluginDispatchPort`] trait, so the
//! Extism types here never leak past the infrastructure boundary.
pub mod log_retention_service;
pub mod log_store;
pub mod manager;
pub mod manifest;
pub mod runtime;
pub use log_retention_service::PluginLogMaintenanceService;
pub use log_store::PluginLogStore;
pub use manager::ExtismPluginManager;
#[cfg(test)]
@@ -71,6 +71,27 @@ impl InvokeOutcome {
matches!(self, InvokeOutcome::Ok)
}
/// The `(level, message)` to record for this outcome in a plugin's log file.
/// `Ok` is an `info` "completed"; every contained failure is a `warn`/`error`
/// carrying its detail. The stable machine key is [`InvokeOutcome::reason`].
pub fn log_detail(&self) -> (&'static str, String) {
match self {
InvokeOutcome::Ok => ("info", "invocation completed".to_string()),
InvokeOutcome::PluginError(e) => ("warn", e.clone()),
InvokeOutcome::Trap(e) => ("error", e.clone()),
InvokeOutcome::Timeout => ("error", "wall-clock timeout".to_string()),
InvokeOutcome::LoadError(e) => ("error", e.clone()),
InvokeOutcome::AbiMismatch { got } => {
("error", format!("abi mismatch: plugin reported {got}"))
}
InvokeOutcome::MissingExport(s) => ("error", format!("missing export: {s}")),
InvokeOutcome::MalformedOutput(e) => ("warn", e.clone()),
InvokeOutcome::MalformedInput { size, max } => {
("warn", format!("input too large: {size} bytes (max {max})"))
}
}
}
/// Stable, machine-readable key for audit logs.
pub fn reason(&self) -> &'static str {
match self {