mirror of
https://github.com/storytold/soundcraft.git
synced 2026-10-14 14:26:46 -04:00
Desktop: write log records to standard error and a rotating log file
The desktop app installed no logger, so every log::warn!/log::error! in the workspace was discarded: the engine's panic report, audio devices that failed to open or broke, plugins that refused their stored state or failed to activate, CLAP plugins' own log messages, files that failed to open. A launch from a desktop menu has no terminal either, so there was nothing to attach to a bug report. apps/soundcraft/src/logging.rs (no new dependency): - standard error plus <settings dir>/logs/soundcraft.log (beside ui.json, Autosave/ and Presets/); each launch rotates the previous log to soundcraft.1.log and .2.log, so the log of a run that crashed survives the next start; the file is capped at 16 MiB - records logged before the settings directory is known are buffered (bounded) and written once the file is attached - default levels: info for soundcraft*, warn for everything else; RUST_LOG replaces them with env_logger-style directives - never panics: an unusable directory or a failed write leaves standard error as the only sink; a poisoned lock is tolerated - runs with SOUNDCRAFT_NO_PREFS (agents' test runs) log to standard error only, so they don't rotate away the user's own logs Realtime audio: a record takes a lock and does I/O, which the audio callback must never do, yet code on the audio thread logs (the cpal error callbacks, the synth's full event queue, a hosted plugin's failed process, a CLAP plugin calling the host's log, the panic hook). The cpal callbacks now mark their thread (soundcraft_mix::mark_audio_thread, re-exported by soundcraft_playback), and the mix engine carries the mark into the rayon workers that render strips for it. A record from a marked thread is not written there: the first is kept in a fixed buffer (try_lock, no allocation, never waits), the rest are counted, and the UI thread writes them every frame (any other thread before its own next record). The logger is installed first in main (before the engine's panic hook) and the file is opened after argument parsing (--version leaves no file). The settings directory moves out of prefs_path into config_dir. The control server's eprintln!s go through the logger (the SOUNDCRAFT_CONTROL_PORT line on standard output stays). Documented in README.md (Getting started > Logs) and docs/architecture.md (Audio).
This commit is contained in:
Gert Pellin committed
1 parent
9334ba0a50
commit
74926df527
8 files changed
+976
-18
No files matched your search
@@ -157,6 +157,28 @@ Useful shortcuts: <kbd>Space</kbd> play/stop, <kbd>⌘</kbd><kbd>=</kbd> Mix/Edi
|
||||
separate, <kbd>⌘</kbd><kbd>D</kbd> duplicate, <kbd>Enter</kbd> new marker, <kbd>⌘</kbd><kbd>⇧</kbd><kbd>N</kbd>
|
||||
new tracks. **Setup › Keyboard Shortcuts** lists them all.
|
||||
|
||||
### Logs
|
||||
|
||||
The desktop app writes its `log` records to standard error and to `logs/soundcraft.log` in the
|
||||
settings directory, beside `ui.json`, `Autosave/` and `Presets/` (Linux `~/.config/soundcraft/logs/`,
|
||||
or `$XDG_CONFIG_HOME/soundcraft/logs/`; macOS `~/Library/Application Support/SoundCraft/logs/`;
|
||||
Windows `%APPDATA%\SoundCraft\logs\`). A start from a desktop menu or the Dock has no terminal, so
|
||||
this file is what to attach to a bug report: the engine's panic report, audio devices that failed to
|
||||
open or broke, plugins that refused their stored state, CLAP plugins' own messages and files that
|
||||
failed to open land there. Each launch moves the previous log to `soundcraft.1.log` (and that one to
|
||||
`soundcraft.2.log`), so the log of a run that crashed survives the next start. The file stops
|
||||
growing at 16 MiB. `--version` writes no file, and runs with `SOUNDCRAFT_NO_PREFS` log to standard
|
||||
error only.
|
||||
|
||||
| Variable | Effect |
|
||||
|---|---|
|
||||
| `RUST_LOG` | Log levels for standard error and the log file. Default: `info` for SoundCraft's own crates, `warn` for everything else. env_logger-style directives replace that, e.g. `RUST_LOG=debug`, `RUST_LOG=warn,soundcraft_mix=trace` or `RUST_LOG=info,wgpu_core=warn`; a directive ending in `*` covers every target starting with it (`soundcraft*=debug`). |
|
||||
| `SOUNDCRAFT_NO_PREFS` | No preferences read or written and no log file (agents' test runs). |
|
||||
|
||||
The realtime audio thread never writes a record itself: the logger keeps the first one it logs
|
||||
(without waiting or allocating), counts the rest, and the UI thread writes them. The logger is
|
||||
`apps/soundcraft/src/logging.rs`. The web app logs to the browser console instead.
|
||||
|
||||
## For agents and scripts
|
||||
|
||||
Everything you can click is also a command with an id and JSON parameters, and the same commands
|
||||
|
||||
@@ -13,12 +13,12 @@ pub fn start(port: u16, ctx: egui::Context) -> Receiver<ControlRequest> {
|
||||
let listener = match TcpListener::bind(("127.0.0.1", port)) {
|
||||
Ok(l) => l,
|
||||
Err(e) => {
|
||||
eprintln!("soundcraft: control server failed to bind 127.0.0.1:{port}: {e}");
|
||||
log::error!("control server failed to bind 127.0.0.1:{port}: {e}");
|
||||
return rx;
|
||||
}
|
||||
};
|
||||
let actual = listener.local_addr().map(|a| a.port()).unwrap_or(port);
|
||||
eprintln!("soundcraft: control server listening on 127.0.0.1:{actual}");
|
||||
log::info!("control server listening on 127.0.0.1:{actual}");
|
||||
println!("SOUNDCRAFT_CONTROL_PORT={actual}");
|
||||
let spawned = std::thread::Builder::new().name("soundcraft-control".into()).spawn(move || {
|
||||
for stream in listener.incoming().flatten() {
|
||||
@@ -28,7 +28,7 @@ pub fn start(port: u16, ctx: egui::Context) -> Receiver<ControlRequest> {
|
||||
}
|
||||
});
|
||||
if let Err(e) = spawned {
|
||||
eprintln!("soundcraft: control thread failed: {e}");
|
||||
log::error!("control thread failed: {e}");
|
||||
}
|
||||
rx
|
||||
}
|
||||
|
||||
@@ -0,0 +1,796 @@
|
||||
//! The desktop app's logger: `log::` records go to standard error and to a log file.
|
||||
//!
|
||||
//! Without a logger every `log::warn!`/`log::error!` in the workspace (the engine's panic report,
|
||||
//! audio devices that failed to open or broke, plugins that refused their stored state or failed
|
||||
//! to activate, CLAP plugins' own log messages, decode errors on import) vanished. A launch from a
|
||||
//! desktop menu has no terminal, so the file is what a bug report can attach:
|
||||
//! `<settings dir>/logs/soundcraft.log`, beside `ui.json`, `Autosave/` and `Presets/`. Each start
|
||||
//! moves the previous log to `soundcraft.1.log` (and that one to `.2`), so the log of a run that
|
||||
//! crashed survives the next launch. Runs without preferences (`SOUNDCRAFT_NO_PREFS`, agents' test
|
||||
//! runs) log to standard error only, so they don't rotate away the user's own logs.
|
||||
//!
|
||||
//! Levels: `info` for SoundCraft's own crates, `warn` for everything else (wgpu and naga are
|
||||
//! chatty). `RUST_LOG` replaces that with env_logger-style directives: `debug`,
|
||||
//! `warn,soundcraft_mix=trace`, `wgpu_core=info`. A directive ending in `*` matches every target
|
||||
//! that starts with it (`soundcraft*=debug`).
|
||||
//!
|
||||
//! Records logged before the settings directory is known are kept (up to [`MAX_PENDING`]) and
|
||||
//! written once the file is attached. Writing never panics: a file that can't be created or
|
||||
//! written leaves standard error as the only sink.
|
||||
//!
|
||||
//! Realtime audio: a record takes a lock and writes to standard error and a file, which the audio
|
||||
//! callback must never do. Code that runs on the audio thread logs anyway (the cpal error callback,
|
||||
//! the synth's full event queue, a hosted plugin's failed `process`, a CLAP plugin calling the
|
||||
//! host's `log` from its audio thread, the panic hook). So the cpal callbacks mark their thread
|
||||
//! (`soundcraft_playback::mark_audio_thread`; the mix engine carries the mark into the worker
|
||||
//! threads that render strips for it), and a record from a marked thread is not written
|
||||
//! there: the first one is kept in a fixed buffer (`try_lock`, no allocation, never waits) and the
|
||||
//! rest are only counted (an atomic). Another thread writes them out: the UI thread every frame
|
||||
//! ([`AppLogger::report_audio_thread`]) and any other thread before its own next record.
|
||||
|
||||
use std::fmt::Write as _;
|
||||
use std::fs::File;
|
||||
use std::io::Write;
|
||||
use std::path::{Path, PathBuf};
|
||||
use std::sync::atomic::{AtomicUsize, Ordering};
|
||||
use std::sync::{Mutex, OnceLock, PoisonError};
|
||||
use std::time::SystemTime;
|
||||
|
||||
use log::LevelFilter;
|
||||
|
||||
/// The current log file's name inside the log directory.
|
||||
pub const LOG_FILE: &str = "soundcraft.log";
|
||||
/// The log directory inside the settings directory.
|
||||
pub const LOG_DIR: &str = "logs";
|
||||
/// How many previous logs are kept (`soundcraft.1.log` … `soundcraft.<KEEP>.log`).
|
||||
pub const KEEP: usize = 2;
|
||||
/// The log file stops growing past this size (a runaway warning can't fill the disk).
|
||||
pub const MAX_FILE_BYTES: u64 = 16 * 1024 * 1024;
|
||||
/// Records kept in memory until the log file is attached.
|
||||
pub const MAX_PENDING: usize = 512;
|
||||
/// The built-in filter when `RUST_LOG` is unset or empty.
|
||||
pub const DEFAULT_FILTER: &str = "warn,soundcraft*=info";
|
||||
/// The longest message kept from the audio thread (longer ones are cut, marked with `…`).
|
||||
pub const REALTIME_MESSAGE_BYTES: usize = 480;
|
||||
/// The longest target kept from the audio thread.
|
||||
const REALTIME_TARGET_BYTES: usize = 96;
|
||||
/// The thread name shown for records from the audio thread.
|
||||
const AUDIO_THREAD: &str = "audio";
|
||||
|
||||
/// Per-target level filter parsed from env_logger-style directives.
|
||||
#[derive(Clone, Debug, PartialEq, Eq)]
|
||||
pub struct Filter {
|
||||
default: LevelFilter,
|
||||
directives: Vec<(String, LevelFilter)>,
|
||||
}
|
||||
|
||||
impl Filter {
|
||||
/// Parse `spec`; unknown levels and empty parts are skipped. Without a bare level, targets no
|
||||
/// directive names log errors only.
|
||||
pub fn parse(spec: &str) -> Filter {
|
||||
let mut f = Filter { default: LevelFilter::Error, directives: Vec::new() };
|
||||
for part in spec.split(',').map(str::trim).filter(|p| !p.is_empty()) {
|
||||
match part.split_once('=') {
|
||||
Some((name, level)) => {
|
||||
let name = name.trim();
|
||||
if let (false, Some(level)) = (name.is_empty(), parse_level(level)) {
|
||||
f.directives.push((name.to_owned(), level));
|
||||
}
|
||||
}
|
||||
None => match parse_level(part) {
|
||||
Some(level) => f.default = level,
|
||||
// A bare target name: everything from it (env_logger does the same).
|
||||
None => f.directives.push((part.to_owned(), LevelFilter::Trace)),
|
||||
},
|
||||
}
|
||||
}
|
||||
f
|
||||
}
|
||||
|
||||
/// The level that applies to `target` (the most specific matching directive wins).
|
||||
pub fn level_for(&self, target: &str) -> LevelFilter {
|
||||
self.directives.iter().filter(|(name, _)| matches(name, target)).max_by_key(|(name, _)| name.len()).map_or(self.default, |(_, level)| *level)
|
||||
}
|
||||
|
||||
/// The most verbose level any target can reach (for `log::set_max_level`).
|
||||
pub fn max(&self) -> LevelFilter {
|
||||
self.directives.iter().map(|(_, level)| *level).fold(self.default, Ord::max)
|
||||
}
|
||||
}
|
||||
|
||||
fn parse_level(s: &str) -> Option<LevelFilter> {
|
||||
s.trim().parse().ok()
|
||||
}
|
||||
|
||||
/// `name` matches `target` itself and its submodules (`a` matches `a` and `a::b`, not `ab`);
|
||||
/// `name*` matches every target starting with `name`.
|
||||
fn matches(name: &str, target: &str) -> bool {
|
||||
match name.strip_suffix('*') {
|
||||
Some(prefix) => target.starts_with(prefix),
|
||||
None => target.strip_prefix(name).is_some_and(|rest| rest.is_empty() || rest.starts_with("::")),
|
||||
}
|
||||
}
|
||||
|
||||
/// `2026-10-08T07:59:17.728Z` (UTC, milliseconds). A clock before 1970 reads as the epoch.
|
||||
pub fn timestamp(t: SystemTime) -> String {
|
||||
let since = t.duration_since(std::time::UNIX_EPOCH).unwrap_or_default();
|
||||
let secs = since.as_secs();
|
||||
let (days, rem) = (secs / 86_400, secs % 86_400);
|
||||
let (y, m, d) = civil_from_days(days);
|
||||
format!("{y:04}-{m:02}-{d:02}T{:02}:{:02}:{:02}.{:03}Z", rem / 3600, rem % 3600 / 60, rem % 60, since.subsec_millis())
|
||||
}
|
||||
|
||||
/// Days since 1970-01-01 to a proleptic Gregorian (year, month, day) (Howard Hinnant's
|
||||
/// `civil_from_days`, unsigned because `timestamp` clamps at the epoch; saturating so an absurd
|
||||
/// clock can't overflow).
|
||||
fn civil_from_days(days: u64) -> (u64, u64, u64) {
|
||||
let z = days.saturating_add(719_468);
|
||||
let era = z / 146_097;
|
||||
let doe = z % 146_097;
|
||||
let yoe = (doe - doe / 1460 + doe / 36_524 - doe / 146_096) / 365;
|
||||
let doy = doe - (365 * yoe + yoe / 4 - yoe / 100);
|
||||
let mp = (5 * doy + 2) / 153;
|
||||
let d = doy - (153 * mp + 2) / 5 + 1;
|
||||
let m = if mp < 10 { mp + 3 } else { mp - 9 };
|
||||
let y = era.saturating_mul(400).saturating_add(yoe).saturating_add(u64::from(m <= 2));
|
||||
(y, m, d)
|
||||
}
|
||||
|
||||
fn numbered(dir: &Path, n: usize) -> PathBuf {
|
||||
if n == 0 { dir.join(LOG_FILE) } else { dir.join(format!("soundcraft.{n}.log")) }
|
||||
}
|
||||
|
||||
/// Shift the previous logs up one (`.log` → `.1.log` → … → `.<KEEP>.log`, the oldest dropped)
|
||||
/// and create a fresh, empty log file in `dir` (created if missing).
|
||||
pub fn rotate(dir: &Path) -> std::io::Result<(PathBuf, File)> {
|
||||
std::fs::create_dir_all(dir)?;
|
||||
for n in (1..=KEEP).rev() {
|
||||
match std::fs::rename(numbered(dir, n - 1), numbered(dir, n)) {
|
||||
Err(e) if e.kind() != std::io::ErrorKind::NotFound => return Err(e),
|
||||
_ => {}
|
||||
}
|
||||
}
|
||||
let path = numbered(dir, 0);
|
||||
let file = File::create(&path)?;
|
||||
Ok((path, file))
|
||||
}
|
||||
|
||||
/// One formatted log line: `<timestamp> <LEVEL> [<thread>] <target>: <message>\n`.
|
||||
pub fn format_line(ts: &str, level: log::Level, thread: &str, target: &str, message: &str) -> String {
|
||||
let message = message.strip_suffix('\n').unwrap_or(message);
|
||||
format!("{ts} {level:<5} [{thread}] {target}: {message}\n")
|
||||
}
|
||||
|
||||
/// Where formatted lines go besides standard error: kept in memory until a file is attached,
|
||||
/// then appended to it until it reaches its size cap.
|
||||
pub struct Sink {
|
||||
file: Option<File>,
|
||||
pending: Vec<String>,
|
||||
dropped: usize,
|
||||
written: u64,
|
||||
max_bytes: u64,
|
||||
capped: bool,
|
||||
}
|
||||
|
||||
impl Sink {
|
||||
pub fn new(max_bytes: u64) -> Sink {
|
||||
Sink { file: None, pending: Vec::new(), dropped: 0, written: 0, max_bytes, capped: false }
|
||||
}
|
||||
|
||||
/// Append `line` to the file, or keep it until [`Sink::attach`].
|
||||
pub fn write(&mut self, line: &str) {
|
||||
if self.file.is_none() {
|
||||
if self.capped {
|
||||
return;
|
||||
}
|
||||
if self.pending.len() < MAX_PENDING {
|
||||
self.pending.push(line.to_owned());
|
||||
} else {
|
||||
self.dropped = self.dropped.saturating_add(1);
|
||||
}
|
||||
return;
|
||||
}
|
||||
self.append(line);
|
||||
}
|
||||
|
||||
/// Start writing to `file`, first the lines kept so far.
|
||||
pub fn attach(&mut self, file: File) {
|
||||
self.file = Some(file);
|
||||
for line in std::mem::take(&mut self.pending) {
|
||||
self.append(&line);
|
||||
}
|
||||
if self.dropped > 0 {
|
||||
let note = format!("{} earlier log lines were dropped before the log file was opened\n", self.dropped);
|
||||
self.dropped = 0;
|
||||
self.append(¬e);
|
||||
}
|
||||
}
|
||||
|
||||
/// There will be no log file: forget the lines kept for it and keep no more.
|
||||
pub fn no_file(&mut self) {
|
||||
self.file = None;
|
||||
self.pending = Vec::new();
|
||||
self.dropped = 0;
|
||||
self.capped = true;
|
||||
}
|
||||
|
||||
fn append(&mut self, line: &str) {
|
||||
if self.capped {
|
||||
return;
|
||||
}
|
||||
let Some(file) = self.file.as_mut() else { return };
|
||||
let len = u64::try_from(line.len()).unwrap_or(u64::MAX);
|
||||
let text = if self.written.saturating_add(len) > self.max_bytes {
|
||||
self.capped = true;
|
||||
format!("log file reached {} bytes; later records go to standard error only\n", self.max_bytes)
|
||||
} else {
|
||||
self.written = self.written.saturating_add(len);
|
||||
line.to_owned()
|
||||
};
|
||||
// A full disk or a vanished file must not take the app down: drop the file sink (and
|
||||
// stop buffering, since no file will come).
|
||||
if file.write_all(text.as_bytes()).is_err() {
|
||||
self.file = None;
|
||||
self.capped = true;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// Text formatted into a fixed buffer: no allocation, cut at a character boundary when full.
|
||||
struct Bounded<const N: usize> {
|
||||
buf: [u8; N],
|
||||
len: usize,
|
||||
cut: bool,
|
||||
}
|
||||
|
||||
impl<const N: usize> Bounded<N> {
|
||||
fn new() -> Self {
|
||||
Bounded { buf: [0; N], len: 0, cut: false }
|
||||
}
|
||||
|
||||
fn as_str(&self) -> &str {
|
||||
// Only whole characters are ever copied in, so this never fails.
|
||||
self.buf.get(..self.len).and_then(|b| std::str::from_utf8(b).ok()).unwrap_or("")
|
||||
}
|
||||
}
|
||||
|
||||
impl<const N: usize> std::fmt::Write for Bounded<N> {
|
||||
fn write_str(&mut self, s: &str) -> std::fmt::Result {
|
||||
let room = N.saturating_sub(self.len);
|
||||
let mut n = s.len().min(room);
|
||||
while !s.is_char_boundary(n) {
|
||||
n = n.saturating_sub(1);
|
||||
}
|
||||
if let (Some(dst), Some(src)) = (self.buf.get_mut(self.len..self.len.saturating_add(n)), s.as_bytes().get(..n)) {
|
||||
dst.copy_from_slice(src);
|
||||
self.len = self.len.saturating_add(n);
|
||||
}
|
||||
if n < s.len() {
|
||||
self.cut = true;
|
||||
}
|
||||
Ok(())
|
||||
}
|
||||
}
|
||||
|
||||
/// The first record the audio thread logged since the last report.
|
||||
struct Held {
|
||||
at: SystemTime,
|
||||
level: log::Level,
|
||||
target: Bounded<REALTIME_TARGET_BYTES>,
|
||||
message: Bounded<REALTIME_MESSAGE_BYTES>,
|
||||
}
|
||||
|
||||
/// Records from the realtime audio thread, waiting for another thread to write them.
|
||||
#[derive(Default)]
|
||||
struct Realtime {
|
||||
/// Records logged on the audio thread since the last report (the held one included).
|
||||
records: AtomicUsize,
|
||||
/// The first of them; the audio thread only `try_lock`s it.
|
||||
held: Mutex<Option<Held>>,
|
||||
}
|
||||
|
||||
impl Realtime {
|
||||
/// Audio thread: count `record` and keep it if it is the first. Never waits, never allocates.
|
||||
fn keep(&self, record: &log::Record<'_>) {
|
||||
self.records.fetch_add(1, Ordering::Relaxed);
|
||||
if let Ok(mut held) = self.held.try_lock()
|
||||
&& held.is_none()
|
||||
{
|
||||
let mut target = Bounded::new();
|
||||
let _ = target.write_str(record.target());
|
||||
let mut message = Bounded::new();
|
||||
let _ = write!(message, "{}", record.args());
|
||||
*held = Some(Held { at: SystemTime::now(), level: record.level(), target, message });
|
||||
}
|
||||
}
|
||||
|
||||
/// Another thread: the lines to write for what the audio thread logged (empty when nothing).
|
||||
fn take_lines(&self) -> String {
|
||||
if self.records.load(Ordering::Relaxed) == 0 {
|
||||
return String::new();
|
||||
}
|
||||
let held = self.held.lock().unwrap_or_else(PoisonError::into_inner).take();
|
||||
let records = self.records.swap(0, Ordering::Relaxed);
|
||||
let mut lines = String::new();
|
||||
if let Some(h) = &held {
|
||||
let mut message = h.message.as_str().to_owned();
|
||||
if h.message.cut {
|
||||
message.push('…');
|
||||
}
|
||||
lines.push_str(&format_line(×tamp(h.at), h.level, AUDIO_THREAD, h.target.as_str(), &message));
|
||||
}
|
||||
let more = records.saturating_sub(usize::from(held.is_some()));
|
||||
if more > 0 {
|
||||
let thread = std::thread::current();
|
||||
let note = format!("{more} more log records from the realtime audio thread were not written (only the first is kept)");
|
||||
lines.push_str(&format_line(×tamp(SystemTime::now()), log::Level::Warn, thread.name().unwrap_or("?"), module_path!(), ¬e));
|
||||
}
|
||||
lines
|
||||
}
|
||||
}
|
||||
|
||||
/// The installed logger: a [`Filter`], standard error and a [`Sink`].
|
||||
pub struct AppLogger {
|
||||
filter: Filter,
|
||||
stderr: bool,
|
||||
sink: Mutex<Sink>,
|
||||
realtime: Realtime,
|
||||
}
|
||||
|
||||
impl AppLogger {
|
||||
pub fn new(filter: Filter, stderr: bool) -> AppLogger {
|
||||
AppLogger { filter, stderr, sink: Mutex::new(Sink::new(MAX_FILE_BYTES)), realtime: Realtime::default() }
|
||||
}
|
||||
|
||||
/// Rotate the logs in `dir` and send records to the fresh file; returns its path.
|
||||
/// An unusable directory leaves standard error as the only sink ([`AppLogger::no_file`]).
|
||||
pub fn attach_dir(&self, dir: &Path) -> Result<PathBuf, String> {
|
||||
match rotate(dir) {
|
||||
Ok((path, file)) => {
|
||||
self.sink.lock().unwrap_or_else(PoisonError::into_inner).attach(file);
|
||||
Ok(path)
|
||||
}
|
||||
Err(e) => {
|
||||
self.no_file();
|
||||
Err(format!("{}: {e}", dir.display()))
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// No log file this run (no settings directory, `SOUNDCRAFT_NO_PREFS`, or the directory can't
|
||||
/// be used): stop keeping records for one.
|
||||
pub fn no_file(&self) {
|
||||
self.sink.lock().unwrap_or_else(PoisonError::into_inner).no_file();
|
||||
}
|
||||
|
||||
/// Write what the audio thread logged since the last report (never call it on the audio thread).
|
||||
pub fn report_audio_thread(&self) {
|
||||
let lines = self.realtime.take_lines();
|
||||
if !lines.is_empty() {
|
||||
self.emit(&lines);
|
||||
}
|
||||
}
|
||||
|
||||
/// Standard error, then the sink; the lock covers one write of already formatted text.
|
||||
fn emit(&self, text: &str) {
|
||||
if self.stderr {
|
||||
// No terminal (a Windows GUI build, a closed pipe) is not an error worth reporting.
|
||||
let _ = std::io::stderr().write_all(text.as_bytes());
|
||||
}
|
||||
self.sink.lock().unwrap_or_else(PoisonError::into_inner).write(text);
|
||||
}
|
||||
}
|
||||
|
||||
impl log::Log for AppLogger {
|
||||
fn enabled(&self, metadata: &log::Metadata<'_>) -> bool {
|
||||
metadata.level() <= self.filter.level_for(metadata.target())
|
||||
}
|
||||
|
||||
fn log(&self, record: &log::Record<'_>) {
|
||||
if !self.enabled(record.metadata()) {
|
||||
return;
|
||||
}
|
||||
if soundcraft_playback::on_audio_thread() {
|
||||
self.realtime.keep(record);
|
||||
return;
|
||||
}
|
||||
self.report_audio_thread();
|
||||
// Formatted before the sink is locked, so a message that logs while it is formatted can't deadlock.
|
||||
let thread = std::thread::current();
|
||||
let line =
|
||||
format_line(×tamp(SystemTime::now()), record.level(), thread.name().unwrap_or("?"), record.target(), &record.args().to_string());
|
||||
self.emit(&line);
|
||||
}
|
||||
|
||||
fn flush(&self) {}
|
||||
}
|
||||
|
||||
/// Install the logger (filter from `RUST_LOG`, else [`DEFAULT_FILTER`]); `None` when another
|
||||
/// logger was installed first. Call [`AppLogger::attach_dir`] or [`AppLogger::no_file`] once the
|
||||
/// settings directory is known.
|
||||
pub fn install() -> Option<&'static AppLogger> {
|
||||
static LOGGER: OnceLock<AppLogger> = OnceLock::new();
|
||||
let spec = std::env::var("RUST_LOG").ok().filter(|s| !s.trim().is_empty());
|
||||
let filter = Filter::parse(spec.as_deref().unwrap_or(DEFAULT_FILTER));
|
||||
let max = filter.max();
|
||||
let logger = LOGGER.get_or_init(|| AppLogger::new(filter, true));
|
||||
log::set_logger(logger).ok()?;
|
||||
log::set_max_level(max);
|
||||
Some(logger)
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
use log::Log;
|
||||
use std::sync::atomic::{AtomicUsize, Ordering};
|
||||
use std::time::{Duration, UNIX_EPOCH};
|
||||
|
||||
fn temp_dir(tag: &str) -> PathBuf {
|
||||
static N: AtomicUsize = AtomicUsize::new(0);
|
||||
let d = std::env::temp_dir().join(format!("soundcraft-logging-{tag}-{}-{}", std::process::id(), N.fetch_add(1, Ordering::Relaxed)));
|
||||
let _ = std::fs::remove_dir_all(&d);
|
||||
d
|
||||
}
|
||||
|
||||
fn read(path: &Path) -> String {
|
||||
std::fs::read_to_string(path).expect("read log")
|
||||
}
|
||||
|
||||
fn record(logger: &AppLogger, level: log::Level, target: &'static str, msg: &str) {
|
||||
logger.log(&log::Record::builder().level(level).target(target).args(format_args!("{msg}")).build());
|
||||
}
|
||||
|
||||
/// Run `f` on a thread the playback crate marks as the realtime audio thread.
|
||||
fn on_audio_thread<T: Send>(f: impl FnOnce() -> T + Send) -> T {
|
||||
std::thread::scope(|s| {
|
||||
s.spawn(|| {
|
||||
soundcraft_playback::mark_audio_thread();
|
||||
f()
|
||||
})
|
||||
.join()
|
||||
.expect("audio thread")
|
||||
})
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_default_filter_shows_soundcraft_info_and_other_crates_warnings() {
|
||||
let f = Filter::parse(DEFAULT_FILTER);
|
||||
assert_eq!(f.level_for("soundcraft"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("soundcraft::control_server"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("soundcraft_playback"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("soundcraft_clap_host::ffi"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("wgpu_core::device"), LevelFilter::Warn);
|
||||
assert_eq!(f.level_for("cpal"), LevelFilter::Warn);
|
||||
assert_eq!(f.max(), LevelFilter::Info);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn directives_follow_env_logger_and_the_most_specific_one_wins() {
|
||||
let f = Filter::parse("info,wgpu_core=error,soundcraft_mix=trace,soundcraft_mix::pdc=off");
|
||||
assert_eq!(f.level_for("eframe"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("wgpu_core::instance"), LevelFilter::Error);
|
||||
assert_eq!(f.level_for("soundcraft_mix::render"), LevelFilter::Trace);
|
||||
assert_eq!(f.level_for("soundcraft_mix::pdc"), LevelFilter::Off);
|
||||
assert_eq!(f.max(), LevelFilter::Trace);
|
||||
// A module name is matched at `::` boundaries, not as a bare prefix.
|
||||
assert_eq!(f.level_for("wgpu_core_extra"), LevelFilter::Info);
|
||||
// A trailing `*` is a prefix.
|
||||
assert_eq!(Filter::parse("warn,soundcraft_ui*=debug").level_for("soundcraft_ui_egui::mix_window"), LevelFilter::Debug);
|
||||
assert_eq!(Filter::parse("warn,soundcraft_ui*=debug").level_for("soundcraft_engine"), LevelFilter::Warn);
|
||||
// A bare target name sets that target to the most verbose level, as env_logger does.
|
||||
assert_eq!(Filter::parse("naga").level_for("naga::front"), LevelFilter::Trace);
|
||||
assert_eq!(Filter::parse("naga").level_for("eframe"), LevelFilter::Error);
|
||||
// Levels are case-insensitive; the last bare level wins.
|
||||
assert_eq!(Filter::parse("debug,WARN").level_for("x"), LevelFilter::Warn);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn hostile_specs_never_panic_and_fall_back_sensibly() {
|
||||
let long = "a".repeat(100_000);
|
||||
let specs = [
|
||||
"",
|
||||
",,,",
|
||||
"=",
|
||||
"==",
|
||||
"=debug",
|
||||
"soundcraft=",
|
||||
"nonsense=loud",
|
||||
"🦀=info",
|
||||
"*",
|
||||
"*=debug",
|
||||
"a=b=c",
|
||||
"warn,,soundcraft=DEBUG",
|
||||
" \t ",
|
||||
"\u{0}",
|
||||
"é*=trace",
|
||||
&long,
|
||||
];
|
||||
for spec in specs {
|
||||
let f = Filter::parse(spec);
|
||||
for target in ["soundcraft", "", "🦀", "é", "a::b"] {
|
||||
let _ = f.level_for(target);
|
||||
}
|
||||
let _ = f.max();
|
||||
}
|
||||
assert_eq!(Filter::parse("warn,,soundcraft=DEBUG").level_for("soundcraft"), LevelFilter::Debug);
|
||||
assert_eq!(Filter::parse("nonsense=loud").level_for("nonsense"), LevelFilter::Error);
|
||||
assert_eq!(Filter::parse("=debug").max(), LevelFilter::Error, "a directive without a name is skipped");
|
||||
assert_eq!(Filter::parse("*=debug").level_for("anything"), LevelFilter::Debug, "a lone `*` matches every target");
|
||||
assert_eq!(Filter::parse("é*=trace").level_for("éa"), LevelFilter::Trace);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn timestamps_are_utc_with_milliseconds() {
|
||||
assert_eq!(timestamp(UNIX_EPOCH), "1970-01-01T00:00:00.000Z");
|
||||
assert_eq!(timestamp(UNIX_EPOCH + Duration::from_millis(1_791_446_357_728)), "2026-10-08T07:59:17.728Z");
|
||||
// Leap day, and the day after it.
|
||||
assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(1_709_164_800)), "2024-02-29T00:00:00.000Z");
|
||||
assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(1_709_251_199)), "2024-02-29T23:59:59.000Z");
|
||||
assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(1_709_251_200)), "2024-03-01T00:00:00.000Z");
|
||||
// 2000 is a leap year (divisible by 400), 2100 is not.
|
||||
assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(951_782_400)), "2000-02-29T00:00:00.000Z");
|
||||
assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(4_107_542_400)), "2100-03-01T00:00:00.000Z");
|
||||
// Before the epoch (a clock set wrong) clamps instead of panicking.
|
||||
assert_eq!(timestamp(UNIX_EPOCH - Duration::from_secs(5)), "1970-01-01T00:00:00.000Z");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn rotation_keeps_the_previous_logs_and_starts_an_empty_file() {
|
||||
let dir = temp_dir("rotate");
|
||||
for run in 1..=4 {
|
||||
let (path, _file) = rotate(&dir).expect("rotate");
|
||||
assert_eq!(path, dir.join(LOG_FILE));
|
||||
assert_eq!(read(&path), "");
|
||||
std::fs::write(&path, format!("run {run}")).expect("write");
|
||||
}
|
||||
assert_eq!(read(&dir.join(LOG_FILE)), "run 4");
|
||||
assert_eq!(read(&dir.join("soundcraft.1.log")), "run 3");
|
||||
assert_eq!(read(&dir.join("soundcraft.2.log")), "run 2");
|
||||
assert!(!dir.join("soundcraft.3.log").exists(), "only {KEEP} old logs are kept");
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn rotation_into_an_unusable_directory_is_an_error_not_a_panic() {
|
||||
let dir = temp_dir("blocked");
|
||||
std::fs::create_dir_all(dir.parent().expect("parent")).expect("tmp");
|
||||
std::fs::write(&dir, "a file where the directory should be").expect("block");
|
||||
assert!(rotate(&dir).is_err());
|
||||
assert!(rotate(&dir.join("below")).is_err());
|
||||
let _ = std::fs::remove_file(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_line_carries_time_level_thread_target_and_message() {
|
||||
assert_eq!(
|
||||
format_line(
|
||||
"2026-10-08T07:59:17.728Z",
|
||||
log::Level::Warn,
|
||||
"main",
|
||||
"soundcraft_mix",
|
||||
"eq_7band: the plugin did not accept its stored state"
|
||||
),
|
||||
"2026-10-08T07:59:17.728Z WARN [main] soundcraft_mix: eq_7band: the plugin did not accept its stored state\n"
|
||||
);
|
||||
// A multi-line message keeps its lines; the record still ends in exactly one newline.
|
||||
assert!(format_line("t", log::Level::Error, "w", "x", "a\nb\n").ends_with("x: a\nb\n"));
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn lines_logged_before_the_file_exists_are_written_when_it_is_attached() {
|
||||
let dir = temp_dir("pending");
|
||||
let (path, file) = rotate(&dir).expect("rotate");
|
||||
let mut sink = Sink::new(MAX_FILE_BYTES);
|
||||
sink.write("early 1\n");
|
||||
sink.write("early 2\n");
|
||||
sink.attach(file);
|
||||
sink.write("late\n");
|
||||
assert_eq!(read(&path), "early 1\nearly 2\nlate\n");
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_pending_buffer_is_bounded_and_says_how_much_it_dropped() {
|
||||
let dir = temp_dir("bounded");
|
||||
let (path, file) = rotate(&dir).expect("rotate");
|
||||
let mut sink = Sink::new(MAX_FILE_BYTES);
|
||||
for i in 0..MAX_PENDING + 5 {
|
||||
sink.write(&format!("line {i}\n"));
|
||||
}
|
||||
sink.attach(file);
|
||||
let text = read(&path);
|
||||
assert_eq!(text.lines().filter(|l| l.starts_with("line ")).count(), MAX_PENDING);
|
||||
assert_eq!(text.matches("5 earlier log lines were dropped").count(), 1, "{text}");
|
||||
assert!(text.contains("line 0\n") && !text.contains(&format!("line {MAX_PENDING}\n")));
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn exactly_max_pending_lines_drop_nothing() {
|
||||
let dir = temp_dir("exact");
|
||||
let (path, file) = rotate(&dir).expect("rotate");
|
||||
let mut sink = Sink::new(MAX_FILE_BYTES);
|
||||
for i in 0..MAX_PENDING {
|
||||
sink.write(&format!("line {i}\n"));
|
||||
}
|
||||
sink.attach(file);
|
||||
let text = read(&path);
|
||||
assert_eq!(text.lines().count(), MAX_PENDING);
|
||||
assert!(!text.contains("dropped"), "{text}");
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_file_stops_at_its_size_cap_with_one_note() {
|
||||
let dir = temp_dir("cap");
|
||||
let (path, file) = rotate(&dir).expect("rotate");
|
||||
let mut sink = Sink::new(100);
|
||||
sink.attach(file);
|
||||
for i in 0..50 {
|
||||
sink.write(&format!("line {i:02} with some padding\n"));
|
||||
}
|
||||
let text = read(&path);
|
||||
assert_eq!(text.lines().filter(|l| l.starts_with("line ")).count(), 3, "{text}");
|
||||
assert_eq!(text.matches("log file reached 100 bytes").count(), 1, "{text}");
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_logger_filters_records_and_writes_them_to_the_attached_file() {
|
||||
let dir = temp_dir("logger");
|
||||
let logger = AppLogger::new(Filter::parse(DEFAULT_FILTER), false);
|
||||
record(&logger, log::Level::Info, "soundcraft", "SoundCraft starting");
|
||||
record(&logger, log::Level::Info, "wgpu_core::device", "too chatty");
|
||||
let path = logger.attach_dir(&dir).expect("attach");
|
||||
assert_eq!(path, dir.join(LOG_FILE));
|
||||
record(&logger, log::Level::Warn, "wgpu_hal::vulkan", "a real warning");
|
||||
record(&logger, log::Level::Debug, "soundcraft", "below info");
|
||||
let text = read(&path);
|
||||
let lines: Vec<&str> = text.lines().collect();
|
||||
assert_eq!(lines.len(), 2, "{text}");
|
||||
assert!(lines.first().is_some_and(|l| l.contains(" INFO [") && l.ends_with("soundcraft: SoundCraft starting")), "{text}");
|
||||
assert!(lines.get(1).is_some_and(|l| l.ends_with("wgpu_hal::vulkan: a real warning")), "{text}");
|
||||
assert!(logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("soundcraft_engine").build()));
|
||||
assert!(!logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("naga").build()));
|
||||
// A second launch rotates: the first log becomes `.1`.
|
||||
let second = AppLogger::new(Filter::parse(DEFAULT_FILTER), false);
|
||||
assert_eq!(second.attach_dir(&dir).expect("attach again"), dir.join(LOG_FILE));
|
||||
assert_eq!(read(&dir.join("soundcraft.1.log")), text);
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn records_from_many_threads_are_whole_lines() {
|
||||
let dir = temp_dir("threads");
|
||||
let logger = AppLogger::new(Filter::parse("info"), false);
|
||||
let path = logger.attach_dir(&dir).expect("attach");
|
||||
std::thread::scope(|s| {
|
||||
for _ in 0..4 {
|
||||
s.spawn(|| {
|
||||
for _ in 0..100 {
|
||||
record(&logger, log::Level::Info, "soundcraft", "from a worker");
|
||||
}
|
||||
});
|
||||
}
|
||||
});
|
||||
let text = read(&path);
|
||||
assert_eq!(text.lines().count(), 400);
|
||||
assert!(text.lines().all(|l| l.ends_with("soundcraft: from a worker")), "{text}");
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn attaching_to_an_unusable_directory_reports_an_error_and_keeps_logging() {
|
||||
let dir = temp_dir("unusable");
|
||||
std::fs::write(&dir, "not a directory").expect("block");
|
||||
let logger = AppLogger::new(Filter::parse("info"), false);
|
||||
record(&logger, log::Level::Info, "soundcraft", "kept for a file");
|
||||
let e = logger.attach_dir(&dir).expect_err("a file is not a log directory");
|
||||
assert!(e.contains(&dir.display().to_string()), "{e}");
|
||||
record(&logger, log::Level::Error, "x", "still fine");
|
||||
let sink = logger.sink.lock().expect("sink");
|
||||
assert!(sink.file.is_none() && sink.pending.is_empty(), "nothing is kept for a file that will not come");
|
||||
drop(sink);
|
||||
let _ = std::fs::remove_file(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_run_without_a_log_file_keeps_nothing_for_one() {
|
||||
let logger = AppLogger::new(Filter::parse("info"), false);
|
||||
record(&logger, log::Level::Info, "soundcraft", "early");
|
||||
logger.no_file();
|
||||
record(&logger, log::Level::Info, "soundcraft", "late");
|
||||
let sink = logger.sink.lock().expect("sink");
|
||||
assert!(sink.file.is_none() && sink.pending.is_empty() && sink.dropped == 0);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_poisoned_lock_does_not_stop_logging() {
|
||||
let dir = temp_dir("poison");
|
||||
let logger = AppLogger::new(Filter::parse("info"), false);
|
||||
let path = logger.attach_dir(&dir).expect("attach");
|
||||
let _ = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
|
||||
let _guard = logger.sink.lock();
|
||||
panic!("poison the sink");
|
||||
}));
|
||||
assert!(logger.sink.is_poisoned());
|
||||
record(&logger, log::Level::Info, "soundcraft", "after the panic");
|
||||
assert!(read(&path).contains("after the panic"));
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
// Realtime audio: the audio thread never takes the sink lock or touches the file.
|
||||
|
||||
#[test]
|
||||
fn an_audio_thread_record_never_waits_for_the_sink() {
|
||||
let dir = temp_dir("rt-nowait");
|
||||
let logger = AppLogger::new(Filter::parse("info"), false);
|
||||
let path = logger.attach_dir(&dir).expect("attach");
|
||||
// Another thread holds the sink (a slow disk, say) while the audio thread logs.
|
||||
let held = logger.sink.lock().expect("sink");
|
||||
let (tx, rx) = std::sync::mpsc::channel();
|
||||
std::thread::scope(|s| {
|
||||
s.spawn(|| {
|
||||
soundcraft_playback::mark_audio_thread();
|
||||
record(&logger, log::Level::Warn, "soundcraft_playback", "audio stream error: device unplugged");
|
||||
let _ = tx.send(());
|
||||
});
|
||||
let done = rx.recv_timeout(Duration::from_secs(10)).is_ok();
|
||||
drop(held);
|
||||
assert!(done, "the audio thread blocked on the sink lock");
|
||||
});
|
||||
assert_eq!(read(&path), "", "nothing is written from the audio thread itself");
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_first_audio_thread_record_is_written_later_with_a_count_of_the_rest() {
|
||||
let dir = temp_dir("rt-report");
|
||||
let logger = AppLogger::new(Filter::parse(DEFAULT_FILTER), false);
|
||||
let path = logger.attach_dir(&dir).expect("attach");
|
||||
on_audio_thread(|| {
|
||||
record(&logger, log::Level::Warn, "soundcraft_playback", "audio stream error: device unplugged");
|
||||
for _ in 0..41 {
|
||||
record(&logger, log::Level::Warn, "soundcraft_playback", "audio stream error: still unplugged");
|
||||
}
|
||||
// Filtered out: neither kept nor counted.
|
||||
record(&logger, log::Level::Debug, "soundcraft_clap_host::plugin", "process failed");
|
||||
});
|
||||
assert_eq!(read(&path), "");
|
||||
logger.report_audio_thread();
|
||||
let text = read(&path);
|
||||
let lines: Vec<&str> = text.lines().collect();
|
||||
assert_eq!(lines.len(), 2, "{text}");
|
||||
assert!(lines.first().is_some_and(|l| l.contains(" WARN [audio] soundcraft_playback: audio stream error: device unplugged")), "{text}");
|
||||
assert!(lines.get(1).is_some_and(|l| l.contains("41 more log records from the realtime audio thread were not written")), "{text}");
|
||||
// Reported once.
|
||||
logger.report_audio_thread();
|
||||
assert_eq!(read(&path), text);
|
||||
// The next record from any other thread reports what the audio thread kept since, first.
|
||||
on_audio_thread(|| record(&logger, log::Level::Error, "soundcraft_clap_host::ffi", "clap plugin: out of voices"));
|
||||
record(&logger, log::Level::Info, "soundcraft", "UI thread");
|
||||
let text = read(&path);
|
||||
let tail: Vec<&str> = text.lines().skip(2).collect();
|
||||
assert_eq!(tail.len(), 2, "{text}");
|
||||
assert!(tail.first().is_some_and(|l| l.contains(" ERROR [audio] soundcraft_clap_host::ffi: clap plugin: out of voices")), "{text}");
|
||||
assert!(tail.get(1).is_some_and(|l| l.ends_with("soundcraft: UI thread")), "{text}");
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_long_audio_thread_record_is_cut_at_a_character_boundary() {
|
||||
let dir = temp_dir("rt-long");
|
||||
let logger = AppLogger::new(Filter::parse("info"), false);
|
||||
let path = logger.attach_dir(&dir).expect("attach");
|
||||
let long = "é".repeat(REALTIME_MESSAGE_BYTES);
|
||||
on_audio_thread(|| record(&logger, log::Level::Warn, "soundcraft", &long));
|
||||
logger.report_audio_thread();
|
||||
let text = read(&path);
|
||||
let message = text.split("soundcraft: ").nth(1).expect("message");
|
||||
assert!(message.ends_with("…\n"), "{text}");
|
||||
assert!(message.len() <= REALTIME_MESSAGE_BYTES + "…\n".len(), "{}", message.len());
|
||||
assert!(message.trim_end_matches(['…', '\n']).chars().all(|c| c == 'é'));
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
}
|
||||
+49
-11
@@ -5,19 +5,27 @@
|
||||
//! `--control <port>` (or `SOUNDCRAFT_CONTROL_PORT`) starts a localhost JSON-lines control server
|
||||
//! (`0` picks a free port and prints it): `{"id":1,"method":"ui.inspect","params":{}}` →
|
||||
//! `{"id":1,"ok":true,"result":…}`. See `soundcraft_ui_egui::control` for the methods.
|
||||
//!
|
||||
//! `log` records go to standard error and `<settings dir>/logs/soundcraft.log` (`RUST_LOG` sets the
|
||||
//! levels); see [`logging`].
|
||||
#![cfg_attr(all(target_os = "windows", not(debug_assertions)), windows_subsystem = "windows")]
|
||||
#![deny(clippy::unwrap_used, clippy::expect_used, clippy::panic, clippy::unimplemented, clippy::todo, clippy::unreachable)]
|
||||
|
||||
mod control_server;
|
||||
mod logging;
|
||||
|
||||
use soundcraft_engine::Engine;
|
||||
use soundcraft_ui_egui::{Services, SoundApp, UiState};
|
||||
use std::sync::Arc;
|
||||
|
||||
struct App(SoundApp);
|
||||
struct App(SoundApp, Option<&'static logging::AppLogger>);
|
||||
|
||||
impl eframe::App for App {
|
||||
fn logic(&mut self, ctx: &egui::Context, _frame: &mut eframe::Frame) {
|
||||
// What the realtime audio thread logged is written here, off that thread.
|
||||
if let Some(logger) = self.1 {
|
||||
logger.report_audio_thread();
|
||||
}
|
||||
self.0.logic(ctx);
|
||||
// Files dropped on the window: sessions open, audio/MIDI import.
|
||||
let dropped: Vec<String> =
|
||||
@@ -39,6 +47,9 @@ impl eframe::App for App {
|
||||
}
|
||||
fn on_exit(&mut self) {
|
||||
save_prefs(&self.0.ui);
|
||||
if let Some(logger) = self.1 {
|
||||
logger.report_audio_thread();
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -57,8 +68,9 @@ fn open_path(app: &mut SoundApp, p: &str) {
|
||||
}
|
||||
}
|
||||
|
||||
fn prefs_path() -> Option<std::path::PathBuf> {
|
||||
let base = if cfg!(target_os = "macos") {
|
||||
/// The per-user settings directory: `ui.json`, `Autosave/`, `Presets/` and `logs/` live here.
|
||||
fn config_dir() -> Option<std::path::PathBuf> {
|
||||
if cfg!(target_os = "macos") {
|
||||
std::env::var_os("HOME").map(|h| std::path::PathBuf::from(h).join("Library/Application Support/SoundCraft"))
|
||||
} else if cfg!(windows) {
|
||||
std::env::var_os("APPDATA").map(|a| std::path::PathBuf::from(a).join("SoundCraft"))
|
||||
@@ -67,12 +79,20 @@ fn prefs_path() -> Option<std::path::PathBuf> {
|
||||
.map(std::path::PathBuf::from)
|
||||
.or_else(|| std::env::var_os("HOME").map(|h| std::path::PathBuf::from(h).join(".config")))
|
||||
.map(|c| c.join("soundcraft"))
|
||||
};
|
||||
base.map(|b| b.join("ui.json"))
|
||||
}
|
||||
}
|
||||
|
||||
fn prefs_path() -> Option<std::path::PathBuf> {
|
||||
config_dir().map(|b| b.join("ui.json"))
|
||||
}
|
||||
|
||||
/// Runs without preferences (`SOUNDCRAFT_NO_PREFS`, agents' test runs) neither read nor write them.
|
||||
fn prefs_enabled() -> bool {
|
||||
std::env::var_os("SOUNDCRAFT_NO_PREFS").is_none()
|
||||
}
|
||||
|
||||
fn load_prefs() -> Option<UiState> {
|
||||
if std::env::var_os("SOUNDCRAFT_NO_PREFS").is_some() {
|
||||
if !prefs_enabled() {
|
||||
return None;
|
||||
}
|
||||
let bytes = std::fs::read(prefs_path()?).ok()?;
|
||||
@@ -80,7 +100,7 @@ fn load_prefs() -> Option<UiState> {
|
||||
}
|
||||
|
||||
fn save_prefs(ui: &UiState) {
|
||||
if std::env::var_os("SOUNDCRAFT_NO_PREFS").is_some() {
|
||||
if !prefs_enabled() {
|
||||
return;
|
||||
}
|
||||
if let Some(p) = prefs_path() {
|
||||
@@ -132,14 +152,14 @@ fn app_icon() -> Option<egui::IconData> {
|
||||
}
|
||||
|
||||
fn main() -> eframe::Result {
|
||||
// First, so every start-up record (and the engine's panic hook, installed with the first
|
||||
// Engine) is captured; see `logging`.
|
||||
let logger = logging::install();
|
||||
let args: Vec<String> = std::env::args().skip(1).collect();
|
||||
if args.iter().any(|a| a == "--version" || a == "-V") {
|
||||
println!("SoundCraft {}", env!("CARGO_PKG_VERSION"));
|
||||
return Ok(());
|
||||
}
|
||||
if std::env::var_os("RUST_LOG").is_none() {
|
||||
// Quiet by default; `RUST_LOG=info` for more.
|
||||
}
|
||||
let demo = args.iter().any(|a| a == "--demo" || a == "--sample");
|
||||
let no_audio = args.iter().any(|a| a == "--no-audio");
|
||||
let control_port: Option<u16> = args
|
||||
@@ -154,6 +174,24 @@ fn main() -> eframe::Result {
|
||||
.filter(|(i, a)| !a.starts_with("--") && !(i > &0 && args.get(i - 1).is_some_and(|p| p == "--control")))
|
||||
.map(|(_, a)| a.clone())
|
||||
.collect();
|
||||
log::info!("SoundCraft {} ({} {})", env!("CARGO_PKG_VERSION"), std::env::consts::OS, std::env::consts::ARCH);
|
||||
// The log file lives in the settings directory; opened after the arguments, so `--version`
|
||||
// leaves no file behind. Records logged until now are written to it first. Runs without
|
||||
// preferences (agents' test runs) log to standard error only, so they don't rotate away the
|
||||
// user's own logs.
|
||||
if let Some(logger) = logger {
|
||||
match config_dir() {
|
||||
_ if !prefs_enabled() => logger.no_file(),
|
||||
Some(dir) => match logger.attach_dir(&dir.join(logging::LOG_DIR)) {
|
||||
Ok(path) => log::info!("log file {}", path.display()),
|
||||
Err(e) => log::warn!("no log file: {e}"),
|
||||
},
|
||||
None => {
|
||||
logger.no_file();
|
||||
log::warn!("no log file: no settings directory (HOME, XDG_CONFIG_HOME or APPDATA is not set)");
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
let engine = if demo { soundcraft_engine::demo::demo_engine() } else { Engine::default() };
|
||||
let mut options = eframe::NativeOptions {
|
||||
@@ -186,7 +224,7 @@ fn main() -> eframe::Result {
|
||||
for f in &files {
|
||||
open_path(&mut app, f);
|
||||
}
|
||||
Ok(Box::new(App(app)))
|
||||
Ok(Box::new(App(app, logger)))
|
||||
}),
|
||||
)
|
||||
}
|
||||
+80
-1
@@ -1000,12 +1000,47 @@ fn structure_fingerprint(s: &Session) -> usize {
|
||||
h.finish() as usize
|
||||
}
|
||||
|
||||
std::thread_local! {
|
||||
static AUDIO_THREAD: std::cell::Cell<bool> = const { std::cell::Cell::new(false) };
|
||||
}
|
||||
|
||||
/// Mark the calling thread as the realtime audio thread (`soundcraft_playback`'s cpal callbacks
|
||||
/// do, every call: one thread-local store). Strips [`MixEngine::render`] hands to worker threads
|
||||
/// count as the audio thread while they render for it. Code that might run there asks
|
||||
/// [`on_audio_thread`] before doing anything that blocks; the desktop app's logger does, so a
|
||||
/// `log::` record from the audio thread never takes a lock or touches a file.
|
||||
pub fn mark_audio_thread() {
|
||||
AUDIO_THREAD.set(true);
|
||||
}
|
||||
|
||||
/// True on the thread [`mark_audio_thread`] marked, and on a worker while it renders strips for
|
||||
/// it. Lock-free and allocation-free.
|
||||
pub fn on_audio_thread() -> bool {
|
||||
AUDIO_THREAD.get()
|
||||
}
|
||||
|
||||
/// Run `f` on this thread as (or as not) the audio thread, then restore the thread's own mark
|
||||
/// (also when `f` unwinds): a pool worker renders for realtime playback and offline bounces alike.
|
||||
#[cfg(not(target_arch = "wasm32"))]
|
||||
fn as_audio_thread(audio: bool, f: impl FnOnce()) {
|
||||
struct Restore(bool);
|
||||
impl Drop for Restore {
|
||||
fn drop(&mut self) {
|
||||
AUDIO_THREAD.set(self.0);
|
||||
}
|
||||
}
|
||||
let _restore = Restore(AUDIO_THREAD.replace(audio));
|
||||
f();
|
||||
}
|
||||
|
||||
/// Process strips, in parallel on native targets when there are enough of them.
|
||||
#[cfg(not(target_arch = "wasm32"))]
|
||||
fn run_strips<T: Send>(work: &mut [T], f: impl Fn(&mut T) + Sync + Send) {
|
||||
use rayon::prelude::*;
|
||||
if work.len() >= 4 {
|
||||
work.par_iter_mut().for_each(f);
|
||||
// The workers render on behalf of this thread: on the audio thread, they are it too.
|
||||
let audio = on_audio_thread();
|
||||
work.par_iter_mut().for_each(|w| as_audio_thread(audio, || f(w)));
|
||||
} else {
|
||||
work.iter_mut().for_each(f);
|
||||
}
|
||||
@@ -1642,6 +1677,50 @@ fn create_plugin(id: &str) -> Option<Box<dyn Plugin>> {
|
||||
.or_else(|| soundcraft_au_host::create(id))
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod audio_thread_tests {
|
||||
use super::*;
|
||||
|
||||
#[test]
|
||||
fn only_a_marked_thread_is_the_audio_thread() {
|
||||
assert!(!on_audio_thread());
|
||||
let marked = std::thread::spawn(|| {
|
||||
let before = on_audio_thread();
|
||||
mark_audio_thread();
|
||||
(before, on_audio_thread())
|
||||
})
|
||||
.join()
|
||||
.unwrap();
|
||||
assert_eq!(marked, (false, true));
|
||||
assert!(!on_audio_thread(), "marking another thread leaves this one alone");
|
||||
}
|
||||
|
||||
/// What `on_audio_thread` says inside each strip job, for strips run from a thread that is
|
||||
/// (or is not) the audio thread.
|
||||
fn seen_by_strips(audio: bool) -> Vec<bool> {
|
||||
std::thread::spawn(move || {
|
||||
if audio {
|
||||
mark_audio_thread();
|
||||
}
|
||||
let mut work = vec![None; 64];
|
||||
run_strips(&mut work, |w| {
|
||||
// Long enough that the pool's workers take part.
|
||||
std::thread::sleep(std::time::Duration::from_millis(1));
|
||||
*w = Some(on_audio_thread());
|
||||
});
|
||||
work.into_iter().map(|w| w.unwrap()).collect()
|
||||
})
|
||||
.join()
|
||||
.unwrap()
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn strips_rendered_for_the_audio_thread_count_as_the_audio_thread_and_only_then() {
|
||||
assert!(seen_by_strips(true).iter().all(|&rt| rt), "a worker rendering for the audio thread is on it");
|
||||
assert!(seen_by_strips(false).iter().all(|&rt| !rt), "the workers don't stay marked afterwards");
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
|
||||
@@ -35,6 +35,10 @@ use std::sync::{Arc, Mutex, PoisonError};
|
||||
|
||||
const BLOCK: usize = 512;
|
||||
|
||||
/// The realtime audio thread marker lives in the mix engine, which carries it into the strips it
|
||||
/// renders on worker threads; the cpal callbacks here set it.
|
||||
pub use soundcraft_mix::{mark_audio_thread, on_audio_thread};
|
||||
|
||||
/// Meter values for the UI.
|
||||
#[derive(Debug, Clone, Default)]
|
||||
pub struct MeterSnapshot {
|
||||
@@ -390,11 +394,19 @@ impl Player {
|
||||
let rate = config.sample_rate.0;
|
||||
let channels = usize::from(config.channels);
|
||||
let mut state = AudioState::new(rx, Arc::clone(&shared), session, f64::from(rate), gtx);
|
||||
let err_fn = |e: cpal::StreamError| log::warn!("audio stream error: {e}");
|
||||
// cpal may call this on the audio thread (on ALSA in a loop while the device
|
||||
// stays broken): marked, so the logger hands the record off instead of writing it.
|
||||
let err_fn = |e: cpal::StreamError| {
|
||||
mark_audio_thread();
|
||||
log::warn!("audio stream error: {e}");
|
||||
};
|
||||
use cpal::traits::{DeviceTrait, StreamTrait};
|
||||
match device.build_output_stream(
|
||||
&config,
|
||||
move |data: &mut [f32], _: &cpal::OutputCallbackInfo| state.fill(data, channels),
|
||||
move |data: &mut [f32], _: &cpal::OutputCallbackInfo| {
|
||||
mark_audio_thread();
|
||||
state.fill(data, channels);
|
||||
},
|
||||
err_fn,
|
||||
None,
|
||||
) {
|
||||
|
||||
@@ -57,6 +57,7 @@ impl Recorder {
|
||||
.build_input_stream(
|
||||
&config,
|
||||
move |data: &[f32], _: &cpal::InputCallbackInfo| {
|
||||
crate::mark_audio_thread();
|
||||
mon.push(data);
|
||||
if !sh.armed.load(Ordering::Relaxed) {
|
||||
backlog.clear();
|
||||
@@ -72,7 +73,11 @@ impl Recorder {
|
||||
backlog.extend_from_slice(data);
|
||||
}
|
||||
},
|
||||
|e| log::warn!("input stream error: {e}"),
|
||||
|e| {
|
||||
// Possibly the audio thread (see `crate::mark_audio_thread`).
|
||||
crate::mark_audio_thread();
|
||||
log::warn!("input stream error: {e}");
|
||||
},
|
||||
None,
|
||||
)
|
||||
.map_err(|e| e.to_string())?;
|
||||
|
||||
@@ -41,6 +41,12 @@ process in parallel; plugin delay compensation aligns every path. The same engin
|
||||
bounces offline (`render_range`) and realtime playback (`soundcraft_playback::Player`, which owns
|
||||
it on the audio thread and receives new session snapshots through a channel).
|
||||
|
||||
The cpal callbacks mark their thread (`soundcraft_playback::mark_audio_thread`). Code that may run
|
||||
there can ask `on_audio_thread()` before doing anything that blocks; the desktop app's logger does,
|
||||
so a `log::` record from the audio thread (a stream error, a full synth event queue, a hosted
|
||||
plugin's failed `process`, a CLAP plugin's own log call) is kept without waiting and written later
|
||||
by the UI thread (see README › Logs).
|
||||
|
||||
## Agent control
|
||||
|
||||
The desktop app's control channel (JSON lines over TCP) exposes engine commands, inspection,
|
||||
|
||||
Reference in new issue
Block a user