stream.close() hangs

[norru]

Hello, stream.close() for non blocking streams occasionally hangs. I have only seen it happen when the code is not optimized, usually after many buffer xrun. Haven't seen happening in --release builds (no xrun).

I'm running the entire audio system in a separate thread, if it helps.

impl SoundSystem for ThreadedSoundSystem {
	fn new() -> Result<ThreadedSoundSystem, self::Error> {
		let portaudio = pa::PortAudio::new()?;
		info!("Detected {:?} devices", portaudio.device_count());
		let settings = portaudio.default_output_stream_settings::<f32>(
			CHANNELS,
			SAMPLE_HZ,
			FRAMES,
		)?;
		let (tx, rx) = channel();

		let dsp = Arc::new(Mutex::new(multiplexer::Multiplexer::new()));
		let dsp_handle = dsp.clone();

		let callback = move |pa::OutputStreamCallbackArgs { buffer, .. }| {
			let buffer: &mut [[f32; CHANNELS as usize]] =
				buffer.to_frame_slice_mut().unwrap();
			sample::slice::equilibrium(buffer);
			// uhm what?
			dsp_handle.lock().unwrap().audio_requested(buffer, SAMPLE_HZ as f64);
			pa::Continue
		};
		let mut stream = portaudio.open_non_blocking_stream(settings, callback)
			.expect("Unable to open audio stream, failure in audio thread");
		let sound_thread = thread::Builder::new().name("SoundControl".to_string()).spawn(move || {
			let thread_id = thread_native_id();
			assert!(set_thread_priority(thread_id,
										ThreadPriority::Max,
										ThreadSchedulePolicy::Normal(NormalThreadSchedulePolicy::Normal)).is_ok());

			info!("Started sound control thread");
			stream.start().expect("Unable to start audio stream");
			'sound_main: loop {
				match rx.recv() {
					Ok(SoundEffect::Eof) => {
						info!("Requested termination, exiting");
						break 'sound_main;
					}
					Ok(sound_effect) => {
						dsp.lock().unwrap().trigger(sound_effect)
					}
					Err(msg) => {
						warn!("Received error {:?}", msg);
						break 'sound_main;
					}
				}
			}
			info!("Closing audio stream");
			match stream.close() { // <--- this line often hangs
				Err(msg) => error!("Unable to close audio stream: {:?}", msg),
				Ok(_) => info!("Close audio stream"),
			}
			info!("Terminating portaudio system");
			portaudio.terminate().expect("Unable to terminate portaudio session");
			info!("Terminated sound control thread");
		})?;

		Ok(ThreadedSoundSystem {
			sound_thread: Some(sound_thread),
			trigger: tx,
		})
	}

	fn open(&mut self) -> Result<(), self::Error> {
		Ok(())
	}

	fn close(&mut self) -> Result<(), self::Error> {
		self.trigger.send(SoundEffect::Eof).ok();
		let result = self.sound_thread.take().unwrap().join();
		match result {
			Ok(_) => Ok(()),
			Err(_) => Err(self::Error::ThreadJoin),
		}
	}
}

Here's the stack trace for all running threads:

Thread 6 (Thread 0x7fffd9bff700 (LWP 23804)):
#0  0x00007ffff6b40147 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007fffee5e0c98 in pa_threaded_mainloop_wait () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#2  0x00007fffea9fa004 in pulse_wait_operation () from /usr/lib/x86_64-linux-gnu/alsa-lib/libasound_module_pcm_pulse.so
#3  0x00007fffea9f897c in ?? () from /usr/lib/x86_64-linux-gnu/alsa-lib/libasound_module_pcm_pulse.so
#4  0x00007ffff70ec362 in ?? () from /usr/lib/x86_64-linux-gnu/libasound.so.2
#5  0x00007ffff70a6230 in snd_pcm_drop () from /usr/lib/x86_64-linux-gnu/libasound.so.2
#6  0x0000555555adf4bb in AlsaStop (stream=stream@entry=0x7ffff5a31c00, abort=<optimized out>) at src/hostapi/alsa/pa_linux_alsa.c:3037
#7  0x0000555555ae1dba in OnExit (data=0x7ffff5a31c00) at src/hostapi/alsa/pa_linux_alsa.c:3388
#8  0x0000555555ae5d17 in CallbackThreadFunc (userData=0x7ffff5a31c00) at src/hostapi/alsa/pa_linux_alsa.c:4180
#9  0x00007ffff6b3a494 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#10 0x00007ffff645fabf in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 5 (Thread 0x7fffda1f4700 (LWP 23803)):
#0  0x00007ffff6b3b6cd in pthread_join () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x0000555555addaad in PaUnixThread_Terminate (self=self@entry=0x7ffff5a31d98, wait=<optimized out>, exitResult=exitResult@entry=0x7fffda1f2f5c) at src/os/unix/pa_unix_util.c:441
#2  0x0000555555ae1cfc in RealStop (stream=0x7ffff5a31c00, abort=<optimized out>) at src/hostapi/alsa/pa_linux_alsa.c:3097
#3  0x0000555555add442 in Pa_CloseStream (stream=0x7ffff5a31c00) at src/common/pa_front.c:1349
#4  0x000055555564a298 in portaudio::stream::{{impl}}::close<portaudio::stream::NonBlocking,portaudio::stream::Output<f32>> (self=0x7fffda1f3650) at /home/nico/.cargo/registry/src/github.com-1ecc6299db9ec823/portaudio-0.7.0/src/stream.rs:1036
#5  0x0000555555735c7b in rust_oids::frontend::audio::{{impl}}::new::{{closure}} () at src/frontend/audio/mod.rs:214
#6  0x0000555555685a03 in std::sys_common::backtrace::__rust_begin_short_backtrace<closure,()> (f=...) at /checkout/src/libstd/sys_common/backtrace.rs:134
#7  0x000055555576a727 in std::thread::{{impl}}::spawn::{{closure}}::{{closure}}<closure,()> () at /checkout/src/libstd/thread/mod.rs:402
#8  0x000055555567e6b3 in std::panic::{{impl}}::call_once<(),closure> (self=..., _args=0) at /checkout/src/libstd/panic.rs:300
#9  0x0000555555646512 in std::panicking::try::do_call<std::panic::AssertUnwindSafe<closure>,()> (data=0x7fffda1f3938 "") at /checkout/src/libstd/panicking.rs:480
#10 0x0000555555b26b6f in panic_unwind::__rust_maybe_catch_panic () at /checkout/src/libpanic_unwind/lib.rs:99
#11 0x00005555556462ad in std::panicking::try<(),std::panic::AssertUnwindSafe<closure>> (f=...) at /checkout/src/libstd/panicking.rs:459
#12 0x00005555556863a8 in std::panic::catch_unwind<std::panic::AssertUnwindSafe<closure>,()> (f=...) at /checkout/src/libstd/panic.rs:365
#13 0x000055555576a591 in std::thread::{{impl}}::spawn::{{closure}}<closure,()> () at /checkout/src/libstd/thread/mod.rs:401
#14 0x000055555576e84b in alloc::boxed::{{impl}}::call_box<(),closure> (self=0x7fffefaf93a0, args=0) at /checkout/src/liballoc/boxed.rs:762
#15 0x0000555555b1d22c in alloc::boxed::{{impl}}::call_once<(),()> () at /checkout/src/liballoc/boxed.rs:772
#16 std::sys_common::thread::start_thread () at /checkout/src/libstd/sys_common/thread.rs:24
#17 std::sys::imp::thread::{{impl}}::new::thread_start () at /checkout/src/libstd/sys/unix/thread.rs:90
#18 0x00007ffff6b3a494 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#19 0x00007ffff645fabf in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 4 (Thread 0x7fffe69f5700 (LWP 23802)):
#0  0x00007ffff6b3c594 in __pthread_mutex_lock_full () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00007fffee37ddce in pa_mutex_lock () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-11.1.so
#2  0x00007fffee5e06bb in ?? () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#3  0x00007fffee5d2070 in pa_mainloop_poll () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#4  0x00007fffee5d2700 in pa_mainloop_iterate () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#5  0x00007fffee5d2790 in pa_mainloop_run () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#6  0x00007fffee5e05f9 in ?? () from /usr/lib/x86_64-linux-gnu/libpulse.so.0
#7  0x00007fffee37ec58 in ?? () from /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-11.1.so
#8  0x00007ffff6b3a494 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#9  0x00007ffff645fabf in clone () from /lib/x86_64-linux-gnu/libc.so.6

Thread 1 (Thread 0x7ffff7fc3340 (LWP 23796)):
#0  0x00007ffff6b3b6cd in pthread_join () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x0000555555b1d2f0 in std::sys::imp::thread::{{impl}}::join () at /checkout/src/libstd/sys/unix/thread.rs:176
#2  0x000055555576a7d5 in std::thread::{{impl}}::join<()> (self=0x7fffffff81c0) at /checkout/src/libstd/thread/mod.rs:1196
#3  0x000055555576ac98 in std::thread::{{impl}}::join<()> (self=...) at /checkout/src/libstd/thread/mod.rs:1318
#4  0x000055555573649b in rust_oids::frontend::audio::{{impl}}::close (self=0x7fffffffd340) at src/frontend/audio/mod.rs:235
#5  0x00005555557341dc in rust_oids::frontend::audio::{{impl}}::close<rust_oids::frontend::audio::ThreadedSoundSystem> (self=0x7fffffffd340) at src/frontend/audio/mod.rs:99
#6  0x000055555573483c in rust_oids::frontend::audio::{{impl}}::drop<rust_oids::frontend::audio::ThreadedSoundSystem> (self=0x7fffffffd340) at src/frontend/audio/mod.rs:152
#7  0x0000555555595415 in core::ptr::drop_in_place<rust_oids::frontend::audio::SoundSystemAlertPlayer<rust_oids::frontend::audio::ThreadedSoundSystem>> () at /checkout/src/libcore/ptr.rs:59
#8  0x000055555577db1e in rust_oids::app::main::main_loop (minion_gene_pool=..., fullscreen=..., width=..., height=...) at src/app/main.rs:177
#9  0x000055555572d53e in rust_oids::app::run (args=...) at src/app/mod.rs:95
#10 0x00005555556ac40f in rust_oids::main () at src/main.rs:70
#11 0x0000555555b26b6f in panic_unwind::__rust_maybe_catch_panic () at /checkout/src/libpanic_unwind/lib.rs:99
#12 0x0000555555b1eadc in std::panicking::try<(),closure> () at /checkout/src/libstd/panicking.rs:459
#13 std::panic::catch_unwind<closure,()> () at /checkout/src/libstd/panic.rs:365
#14 std::rt::lang_start () at /checkout/src/libstd/rt.rs:59
#15 0x00005555556ac5de in main ()
#16 0x00007ffff63972e1 in __libc_start_main () from /lib/x86_64-linux-gnu/libc.so.6
#17 0x000055555558730a in _start ()

[norru]

I think I found the issue. The auidio stream was being started by a thread and terminated by another. The Linux build didn't complain, but it was easily spotted by running the code on Windows (library warns loudly!).

Doing start/stop in the same thread appears to fix the problem.

Sorry for the inconvenience, thanks anyway!

[norru]

I may have spoken too soon. Got the problem again, within same thread. Still investigating.

[monoAtomic-audio]

@norru any updates? only a few years later :D

[bernardolansing]

You probably don't need help with this anymore as it's been several years, but I came across a similar situation and I was able to solve it.

I was holding the stream object, along with other stuff, all under the same mutex. So I had to lock the mutex to call stream.close(); the problem is that this function halts until a final stream callback is finished. But the callback also tried to lock the mutex, so I was running into a deadlock.

Mine is probably a bad design, but I was able to solve it by simply replacing Mutex::lock() by Mutex::try_lock() from within the stream callback. try_lock will return an error if the mutex is already locked somewhere else, so if that was the case I'd just return portaudio::Continue and the problem was solved.