diff --git a/issues/audio/cpal-backend-hardcodes-the-format.md b/issues/audio/cpal-backend-hardcodes-the-format.md index 3b27aba0842..7b341a81daf 100644 --- a/issues/audio/cpal-backend-hardcodes-the-format.md +++ b/issues/audio/cpal-backend-hardcodes-the-format.md @@ -11,6 +11,19 @@ client and therefore effectively untested. The backend also `assert_eq!`s the device rate against a compile-time constant, so changing the driver's rate aborts every cpal app. +**`Drop`'s bound on soundd is built from copies the same way.** A dropped +`Stream` waits for soundd to close its signal pipe for at most soundd's 5 ms +fade, in whole periods, plus the 8 periods of the stream's ring: 1280 frames at +44100 Hz (`RELEASE_WITHIN`). Past it, `Drop` refuses by name and returns. The +fade (`toyos_mixer::ramp_frames`) and the ring depth (soundd's `slot_count`, see +`issues/audio/client-ring-depth-is-the-devices-pipeline-depth.md`) are copies: +`StreamOpenResponse.slot_count` reaches `AudioStream::open` and stays private, +and no message carries the fade. If soundd's fade grows or a device's pipeline +deepens, the bound shrinks under what soundd needs, and a healthy soundd is +refused. That part goes when `AudioStream` says the ring depth and the fade and +the host derives `RELEASE_WITHIN` from them, which changes `toyos/src` and the +audio protocol. + Deferred to the quiet-tree window, not neglected: editing that fork needs `.cargo/config.toml` path overrides, which redirect cpal for **every** agent in the tree. Same scheduling constraint as the fork lint audit. diff --git a/issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md b/issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md index 01804c4d582..61070a4c295 100644 --- a/issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md +++ b/issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md @@ -13,7 +13,6 @@ FAIL hda_client_stall: soundd resumed 0 time(s) — the second stream did not fi ``` The job itself exits 0 and prints `stalled 8 then 2 times, soundd survived`. -Its cause is not measured; whether the judge or soundd is wrong is open. ## Measured @@ -44,6 +43,40 @@ The `testcases` boot's log, from the job's spawn to its end, in order: the previous client's removal at `6.275` and its open at `6.333`, so `client_stall_on_metal`'s `resumes < 2` reds on that span too. +## Measured once a job's stream is gone before the job exits + +The `testcases` boot of the orchestrator's T14 `--metal hda_tone` run at +`1621eb5f0` (#641), from the tone's removal to the stall's end, in order: + +``` +{… 5.670 soundd} soundd: client 0 removed (closed) +{… 5.670 soundd} soundd: wakes=645 … clients=0 … +[… 5.670 cpu4] exit: test_rs_audio_tone pid=11 code=0 cpu=2ms +[… 5.672 cpu7] spawn: /system/bin/test_rs_hda_client_stall pid=12 … +{… 5.673 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 +{… 5.673 soundd} soundd: client 0 connected (id=1) +{… 7.830 soundd} soundd: client 1 removed (closed) +{… 7.830 soundd} soundd: wakes=79 … clients=0 … +{… 7.854 soundd} soundd: suspended +{… 8.130 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 +{… 8.131 soundd} soundd: client 0 connected (id=2) +{… 8.131 soundd} soundd: resumed +{… 9.040 soundd} soundd: client 2 removed (closed) +{… 9.040 soundd} soundd: wakes=465 … clients=0 … +{… 9.063 soundd} soundd: suspended +``` + +- The tone's stream is removed, and its session flushed, before its job + exits; the stall's first stream opens 3 ms after that exit. +- soundd suspends 20 to 25 ms after the last removal: `7.830`→`7.854` and + `9.040`→`9.063` here, `8.565`→`8.585` and `9.755`→`9.780` above. +- So the first stream opens on a soundd that has not suspended, which is not + the premise `client_stall_on_metal` asks of it. The judge reads this log as: + +``` +FAIL hda_client_stall: soundd resumed 1 time(s) — the second stream did not find a suspended daemon, so nothing here tests a resume: +``` + ## Exit condition `hda_client_stall` PASS on the orchestrator's T14 run of the head that lands diff --git a/issues/audio/hda-tone-reads-underruns-on-the-t14-where-its-judge-wants-none.md b/issues/audio/hda-tone-reads-underruns-on-the-t14-where-its-judge-wants-none.md deleted file mode 100644 index 662d835b131..00000000000 --- a/issues/audio/hda-tone-reads-underruns-on-the-t14-where-its-judge-wants-none.md +++ /dev/null @@ -1,50 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-29 ---- - -# `hda_tone` reads underruns on the T14 where its judge wants none - -The T14 run of `wt/toyos-metaljudges` at `f5c80264f` reds the row with: - -``` -FAIL hda_tone: soundd filled 104 period(s) the tone client had not covered, on a client that keeps its ring full: -``` - -The job itself exits 0 and prints `tone done`. Its cause is not measured; -whether the judge or soundd is wrong is open. - -The T14 run of `main` at `7e151819` reddened the row earlier, on `the -testcases's log carried no kernel output at all`. - -## Measured - -The `testcases` boot's log over the window the judge printed, selected lines in -order: - -``` -{… 3.021 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 -{… 3.021 soundd} soundd: client 0 connected (id=0) -{… 3.021 soundd} soundd: resumed -{… 5.024 soundd} soundd: wakes=984 completions=689 submitted=697 underruns=0 drains=0 … clients=1 … -[… 6.252 cpu0 tid=1] exit: test_rs_audio_tone tid=1 code=0 cpu=12ms (after 48 like it suppressed) -{… 6.252 pid=8 test-runner} tone done -{… 6.252 test-runner} ===TEST_END test_rs_audio_tone exit=0=== -{… 6.252 test-runner} ===TEST_START test_rs_hda_client_stall=== -[… 6.253 cpu7] spawn: /system/bin/test_rs_hda_client_stall pid=9 … -{… 6.254 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 -{… 6.254 soundd} soundd: client 1 connected (id=1) -{… 6.258 soundd} soundd: client 0 removed (closed) -{… 7.024 soundd} soundd: wakes=989 completions=688 submitted=688 underruns=39 drains=0 … clients=1 … -{… 8.412 soundd} soundd: client 1 removed (closed) -{… 8.418 soundd} soundd: wakes=741 completions=479 submitted=479 underruns=65 drains=0 … clients=0 … -``` - -The printed window carries three stats lines, with `underruns=0`, `underruns=39` -and `underruns=65`, which sum to the 104 the row names. - -## Exit condition - -`hda_tone` PASS on the orchestrator's T14 run of the head that lands the fix, -and this file is deleted. diff --git a/tests/checks/audio.rs b/tests/checks/audio.rs index 2bfc573c6f7..df340713435 100644 --- a/tests/checks/audio.rs +++ b/tests/checks/audio.rs @@ -48,6 +48,50 @@ pub fn judges_verdict() -> Result<(), String> { &format!("{}{{0.600 soundd}} {NULL_SINK}\n{next}", tone(stats(0, 0, 0))), false, )?; + // The next job's stream connected before soundd let the tone's go, so the + // tone's last window is both streams' whatever it counted. + judged( + "a tone another job's stream joined", + tone_on_metal, + &format!( + "{configured}{}{{1.000 soundd}} soundd: client 0 connected (id=1)\n{}{next}\ + {{3.000 soundd}} soundd: client 1 connected (id=2)\n\ + {{3.000 soundd}} soundd: client 1 removed (closed)\n{}\ + {{4.000 soundd}} soundd: client 2 removed (closed)\n{}", + spawn("test_rs_audio_tone"), + stats(0, 1, 0), + stats(0, 1, 0), + stats(0, 0, 0), + ), + false, + )?; + judged( + "a tone whose window ended before its stream connected", + tone_on_metal, + &format!( + "{configured}{}{{0.900 soundd}} soundd: client 0 removed (closed)\n{}{}{next}", + spawn("test_rs_audio_tone"), + stats(0, 0, 0), + session(stats(0, 1, 0), "closed", stats(0, 0, 0)) + ), + false, + )?; + // Another job's stream, held since before the spawn, is still held when the + // tone's connects: one connect in the window, and two removals. + judged( + "a tone beside a stream soundd held at its spawn", + tone_on_metal, + &format!( + "{configured}{{0.900 soundd}} soundd: client 0 connected (id=0)\n{}\ + {{1.000 soundd}} soundd: client 1 connected (id=1)\n{}\ + {{2.500 soundd}} soundd: client 0 removed (closed)\n\ + {{3.000 soundd}} soundd: client 1 removed (closed)\n{}{next}", + spawn("test_rs_audio_tone"), + stats(0, 2, 0), + stats(0, 0, 0), + ), + false, + )?; let stall = |second: String, rest: &str| { format!( diff --git a/tests/common/audio.rs b/tests/common/audio.rs index 5c3f9601bf8..ec089233663 100644 --- a/tests/common/audio.rs +++ b/tests/common/audio.rs @@ -10,6 +10,10 @@ use super::serial::Serial; /// that carries `clients=0`, which soundd writes after the removal — and not at /// the next job's spawn, which can land before it. A job that plays nothing /// (`sessions` of 0) ends at the next test binary's spawn. +/// +/// Sessions are refused unless each is one stream: soundd counts one window +/// across every client it holds, so a session another job's stream shared has +/// no count that is the job's alone. fn job_window<'a>(log: &'a str, job: &str, sessions: usize) -> Result<&'a str, String> { let head = format!("spawn: /system/bin/{job} "); let at = log.find(&head).ok_or_else(|| format!("no `{head}` record: {job} never ran"))?; @@ -32,7 +36,21 @@ fn job_window<'a>(log: &'a str, job: &str, sessions: usize) -> Result<&'a str, S })?; end = rest[flushed..].find('\n').map_or(rest.len(), |nl| flushed + nl + 1); } - Ok(&rest[..end]) + let window = &rest[..end]; + let said = |what: &str| { + window.lines().filter(|l| l.contains("soundd: client ") && l.contains(what)).count() + }; + // A removal counts too: a stream soundd held before the spawn connected + // outside the window and leaves inside it. + let (streams, removed) = (said(" connected (id="), said(" removed (")); + if streams != sessions || removed != sessions { + return Err(format!( + "soundd connected {streams} and removed {removed} stream(s) in {job}'s {sessions} \ + session(s): another job's stream shared soundd with {job}'s, and no count in the \ + window is {job}'s alone:\n{window}" + )); + } + Ok(window) } /// What soundd's flush on its last client leaving carries, and no other stats diff --git a/tests/toyos-rust-tests/Cargo.lock b/tests/toyos-rust-tests/Cargo.lock index 5879429cd2b..a7acd1875f0 100644 --- a/tests/toyos-rust-tests/Cargo.lock +++ b/tests/toyos-rust-tests/Cargo.lock @@ -337,7 +337,7 @@ dependencies = [ [[package]] name = "cpal" version = "0.18.0" -source = "git+https://github.com/ToyOSOrg/cpal?branch=toyos-0.18.0#7e9775d5dc50b0da933fb947c806bd420ff6e85d" +source = "git+https://github.com/ToyOSOrg/cpal?branch=toyos-0.18.0#29180f7b5a524e6709d30c010e7e0280cd82ccda" dependencies = [ "alsa", "block2 0.6.2", diff --git a/tests/toyos-rust-tests/src/bin/cpal_drop_unreleased.rs b/tests/toyos-rust-tests/src/bin/cpal_drop_unreleased.rs new file mode 100644 index 00000000000..092814e2d0c --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/cpal_drop_unreleased.rs @@ -0,0 +1,146 @@ +//! cpal's ToyOS host, dropped while its stream's server never lets go of it. +//! +//! This binary is the stream's server: it answers the open as soundd does, and +//! then holds the signal pipe open without writing it until the client's +//! `Drop` has come back — a soundd whose mix loop has stopped. Its child, the +//! same binary with `client`, reaches it as `soundd`, builds a stream through +//! cpal and drops it unplayed. The stream thread sends the close and waits on +//! the pipe; `Drop` has to come back with the refusal by name through the error +//! callback rather than wait for good. One signal then has to end the stream +//! thread while its process lives, so the stream's connection closes as it +//! would for soundd. +//! +//! No sound is played and soundd is not involved. + +use std::io::{BufRead, BufReader, Read}; +use std::os::toyos::process::CommandExt; +use std::process::{Command, Stdio}; +use std::sync::mpsc; + +use cpal::traits::{DeviceTrait, HostTrait}; +use toyos::audio::{ + StreamOpenRequest, StreamOpenResponse, MSG_STREAM_CLOSE, MSG_STREAM_OPEN, MSG_STREAM_OPENED, +}; +use toyos::ipc::IpcError; +use toyos::shm::SharedMemory; +use toyos::{namespace, port}; +use toyos_abi::audio::AudioSlotHeader; +use toyos_abi::syscall::SVC_LABEL; + +const SELF: &str = "/system/bin/test_rs_cpal_drop_unreleased"; + +/// cpal's ToyOS host's words for a soundd that did not let go. +const REFUSAL: &str = "soundd did not let go of the closed stream within "; + +/// What soundd answers a 44100 Hz stereo open with, which is the one stream +/// cpal's ToyOS host opens. +const OPENED: StreamOpenResponse = StreamOpenResponse { + client_period_frames: 128, + client_period_bytes: 512, + device_sample_rate: 44_100, + device_channels: 2, + slot_count: 8, +}; + +fn main() { + match std::env::args().nth(1).as_deref() { + None => serve(), + Some("client") => client(), + Some(other) => panic!("no role {other:?}"), + } +} + +fn serve() { + let (acceptor, connector) = port::create().expect("a port"); + let names = namespace::build() + .add("soundd", &connector) + .finish() + .expect("a namespace naming this binary soundd"); + let mut child = Command::new(SELF) + .arg("client") + .endow(SVC_LABEL, names.into_raw().0) + .stdin(Stdio::piped()) + .stdout(Stdio::piped()) + .spawn() + .expect("spawn the client"); + + let conn = acceptor.accept().expect("the client's connection"); + let (kind, _): (u32, StreamOpenRequest) = conn.recv().expect("the client's open"); + assert_eq!(kind, MSG_STREAM_OPEN, "the client's first frame is not an open"); + let ring = SharedMemory::create( + AudioSlotHeader::SIZE + OPENED.slot_count as usize * OPENED.client_period_bytes as usize, + ) + .expect("a ring"); + let (signal_read, signal_write) = toyos::pipe_pair().expect("a signal pipe"); + conn.send_with_handles( + &[ring.share().expect("the ring to share"), signal_read.into_raw()], + MSG_STREAM_OPENED, + &OPENED, + ) + .expect("the open answered"); + + let close = conn.recv_header().expect("the client's close"); + assert_eq!(close.msg_type, MSG_STREAM_CLOSE, "the dropped stream did not close"); + + // The write end is held until the client has gone, so nothing but its + // own deadline can end its wait. The client says the refusal once `Drop` + // has returned with it. + let mut said = String::new(); + BufReader::new(child.stdout.take().expect("the client's stdout")) + .read_line(&mut said) + .expect("the client's line"); + assert!(said.starts_with("client: "), "the client said {said:?} before its drop came back"); + print!("{said}"); + + signal_write.write(&[1]).expect("a signal to the stream thread"); + match conn.recv_header() { + Err(IpcError::Disconnected) => {} + other => panic!( + "the stream's connection gave {:?} after its close, not its end", + other.map(|h| h.msg_type) + ), + } + // The client exits once its stdin closes, so the connection's end above + // was the stream thread's. + drop(child.stdin.take()); + let status = child.wait().expect("wait for the client"); + drop(signal_write); + assert!(status.success(), "the client exited {status:?}"); + println!( + "cpal's drop came back while its server held the signal pipe, and the next signal \ + ended its stream thread" + ); +} + +fn client() { + let device = cpal::default_host() + .default_output_device() + .expect("the ToyOS host's output"); + let config = device.default_output_config().expect("its config"); + let (said, heard) = mpsc::channel(); + let stream = device + .build_output_stream( + config.into(), + |_: &mut [i16], _: &cpal::OutputCallbackInfo| { + unreachable!("a stream never played is never asked for audio") + }, + move |error: cpal::Error| said.send(error).expect("main hears every error"), + None, + ) + .expect("the open answered"); + drop(stream); + + let errors: Vec = heard.try_iter().collect(); + assert!( + matches!( + errors.as_slice(), + [refused] if refused.kind() == cpal::ErrorKind::HostUnavailable + && refused.to_string().starts_with(REFUSAL) + ), + "the drop came back with {errors:?}, not the refusal" + ); + println!("client: {}", errors[0]); + + let mut rest = Vec::new(); + std::io::stdin().read_to_end(&mut rest).expect("the server's end of stdin"); +} diff --git a/tests/toyos-rust-tests/src/tone.rs b/tests/toyos-rust-tests/src/tone.rs index 72e0e5f7e38..12088219b80 100644 --- a/tests/toyos-rust-tests/src/tone.rs +++ b/tests/toyos-rust-tests/src/tone.rs @@ -27,6 +27,8 @@ pub fn play_tone() { let done = Arc::new(AtomicBool::new(false)); let done2 = done.clone(); let position = Arc::new(AtomicU64::new(0)); + let failed = Arc::new(AtomicBool::new(false)); + let failed2 = failed.clone(); let stream = device .build_output_stream( @@ -48,7 +50,10 @@ pub fn play_tone() { done2.store(true, Ordering::Relaxed); } }, - |err| eprintln!("audio error: {err}"), + move |err| { + eprintln!("audio error: {err}"); + failed2.store(true, Ordering::Relaxed); + }, None, ) .expect("failed to build audio stream"); @@ -61,4 +66,7 @@ pub fn play_tone() { // Let the tail of the tone drain through soundd and the device. std::thread::sleep(std::time::Duration::from_millis(200)); + + drop(stream); + assert!(!failed.load(Ordering::Relaxed), "the tone's stream reported an error, printed above"); } diff --git a/userland/Cargo.lock b/userland/Cargo.lock index 600a2d3b028..5489d455e17 100644 --- a/userland/Cargo.lock +++ b/userland/Cargo.lock @@ -605,7 +605,7 @@ dependencies = [ [[package]] name = "cpal" version = "0.18.0" -source = "git+https://github.com/ToyOSOrg/cpal?branch=toyos-0.18.0#7e9775d5dc50b0da933fb947c806bd420ff6e85d" +source = "git+https://github.com/ToyOSOrg/cpal?branch=toyos-0.18.0#29180f7b5a524e6709d30c010e7e0280cd82ccda" dependencies = [ "alsa", "block2 0.6.2",