search

mozilla / cubeb-coreaudio-rs

The audio backend of Firefox on Mac OS X.
ISC License
25 stars 10 forks source link

assertion failed: stm.switching_device #102

Closed achronop closed 4 years ago

achronop commented 4 years ago

This is the error line:

thread '<unnamed>' panicked at 'assertion failed: stm.switching_device.load(Ordering::SeqCst)', src/backend/mod.rs:647:25

Secnario:

  1. Duplex call to the default devices
  2. Change the default output
  3. Change the default input, then crashed

The full logs:

mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:2595: (0x7fb0f6e14550) Initialize input by device info: device_info { id: 217, flags: DEV_INPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2606: (0x7fb0f6e14550) Opening input side: rate 44100, channels 1, format Float32LE, layout (empty), prefs NONE, latency in frames 128.
mod.rs:2635: (0x7fb0f6e14550) Input hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1351: The new buffer frames size of AudioUnit 0x8cef706f for INPUT is 128
mod.rs:2723: (0x7fb0f6e14550) Input audiounit init with device 217 successfully.
mod.rs:2731: (0x7fb0f6e14550) Initialize output by device info: device_info { id: 203, flags: DEV_OUTPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2742: (0x7fb0f6e14550) Opening output side: rate 44100, channels 2, format Float32LE, layout FRONT_LEFT | FRONT_RIGHT, prefs NONE, latency in frames 128.
mod.rs:2780: (0x7fb0f6e14550) Output hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1351: The new buffer frames size of AudioUnit 0x8cef7070 for OUTPUT is 128
mod.rs:2885: (0x7fb0f6e14550) Output audiounit init with device 203 successfully.
mod.rs:2328: (0x7fb0f6e14550) Cubeb stream init successful.
stream_init succeed
state is CUBEB_STATE_STARTED
mod.rs:3598: Cubeb stream (0x7fb0f6e14550) started successfully.
stream_start succeed
press `q` to abort or `h` for help
mod.rs:630: Dropping 1792 frames in input buffer.
mod.rs:774: (0x7fb0f6e14550) Audio device changed, 1 events.
mod.rs:782: Event[0] - mSelector == kAudioHardwarePropertyDefaultOutputDevice for id=1
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:2595: (0x7fb0f6e14550) Initialize input by device info: device_info { id: 217, flags: DEV_INPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2606: (0x7fb0f6e14550) Opening input side: rate 44100, channels 1, format Float32LE, layout (empty), prefs NONE, latency in frames 128.
mod.rs:2635: (0x7fb0f6e14550) Input hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1280: The buffer frame size of AudioUnit 0x8cef7075 for INPUT is already 128
mod.rs:2723: (0x7fb0f6e14550) Input audiounit init with device 217 successfully.
mod.rs:2731: (0x7fb0f6e14550) Initialize output by device info: device_info { id: 217, flags: DEV_OUTPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2742: (0x7fb0f6e14550) Opening output side: rate 44100, channels 2, format Float32LE, layout FRONT_LEFT | FRONT_RIGHT, prefs NONE, latency in frames 128.
mod.rs:2780: (0x7fb0f6e14550) Output hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1280: The buffer frame size of AudioUnit 0x8cef7076 for OUTPUT is already 128
mod.rs:2885: (0x7fb0f6e14550) Output audiounit init with device 217 successfully.
mod.rs:774: (0x7fb0f6e14550) Audio device changed, 1 events.
mod.rs:806: Event[0] - mSelector == kAudioHardwarePropertyDefaultInputDevice for id=1
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:641: (0x7fb0f6e14550) Missing Frames: device switching, will append 128 frames of input silence.
mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:2595: (0x7fb0f6e14550) Initialize input by device info: device_info { id: 196, flags: DEV_INPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2606: (0x7fb0f6e14550) Opening input side: rate 44100, channels 1, format Float32LE, layout (empty), prefs NONE, latency in frames 128.
mod.rs:2635: (0x7fb0f6e14550) Input hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1351: The new buffer frames size of AudioUnit 0x8cef707d for INPUT is 128
mod.rs:2723: (0x7fb0f6e14550) Input audiounit init with device 196 successfully.
mod.rs:2731: (0x7fb0f6e14550) Initialize output by device info: device_info { id: 217, flags: DEV_OUTPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2742: (0x7fb0f6e14550) Opening output side: rate 44100, channels 2, format Float32LE, layout FRONT_LEFT | FRONT_RIGHT, prefs NONE, latency in frames 128.
mod.rs:2780: (0x7fb0f6e14550) Output hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1280: The buffer frame size of AudioUnit 0x8cef707e for OUTPUT is already 128
mod.rs:2885: (0x7fb0f6e14550) Output audiounit init with device 217 successfully.
thread '<unnamed>' panicked at 'assertion failed: stm.switching_device.load(Ordering::SeqCst)', src/backend/mod.rs:647:25
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
fatal runtime error: Rust panics must be rethrown
Abort trap: 6
achronop commented 4 years ago

More logs without devices changing,

  1. Duplex call to internal mic and external usb device. The assert is hit before the call start:

mod.rs:218: Requesting default system device.
mod.rs:2595: (0x7f9cd6d194e0) Initialize input by device info: device_info { id: 196, flags: DEV_INPUT }
mod.rs:2606: (0x7f9cd6d194e0) Opening input side: rate 44100, channels 1, format Float32LE, layout (empty), prefs NONE, latency in frames 128.
mod.rs:2635: (0x7f9cd6d194e0) Input hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1351: The new buffer frames size of AudioUnit 0x8cfec06f for INPUT is 128
mod.rs:2723: (0x7f9cd6d194e0) Input audiounit init with device 196 successfully.
mod.rs:2731: (0x7f9cd6d194e0) Initialize output by device info: device_info { id: 217, flags: DEV_OUTPUT | DEV_SYSTEM_DEFAULT }
mod.rs:2742: (0x7f9cd6d194e0) Opening output side: rate 44100, channels 2, format Float32LE, layout FRONT_LEFT | FRONT_RIGHT, prefs NONE, latency in frames 128.
mod.rs:2780: (0x7f9cd6d194e0) Output hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1351: The new buffer frames size of AudioUnit 0x8cfec070 for OUTPUT is 128
mod.rs:2885: (0x7f9cd6d194e0) Output audiounit init with device 217 successfully.
mod.rs:2328: (0x7f9cd6d194e0) Cubeb stream init successful.
stream_init succeed
state is CUBEB_STATE_STARTED
mod.rs:3598: Cubeb stream (0x7f9cd6d194e0) started successfully.
stream_start succeed
press `q` to abort or `h` for help
thread '<unnamed>' panicked at 'assertion failed: stm.switching_device.load(Ordering::SeqCst)', src/backend/mod.rs:647:25
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
fatal runtime error: Rust panics must be rethrown
Abort trap: 6
achronop commented 4 years ago

Same scenario with previous comments plus verbose logs on:


Init cubeb backend: audiounit-rust
collection device type is UNKNOWN
mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:213: Creating a default device info.
mod.rs:218: Requesting default system device.
mod.rs:2595: (0x7fd6d551eae0) Initialize input by device info: device_info { id: 196, flags: DEV_INPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2606: (0x7fd6d551eae0) Opening input side: rate 44100, channels 1, format Float32LE, layout (empty), prefs NONE, latency in frames 128.
mod.rs:2635: (0x7fd6d551eae0) Input hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1351: The new buffer frames size of AudioUnit 0x8d26d06f for INPUT is 128
mod.rs:2723: (0x7fd6d551eae0) Input audiounit init with device 196 successfully.
mod.rs:2731: (0x7fd6d551eae0) Initialize output by device info: device_info { id: 217, flags: DEV_OUTPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
mod.rs:2742: (0x7fd6d551eae0) Opening output side: rate 44100, channels 2, format Float32LE, layout FRONT_LEFT | FRONT_RIGHT, prefs NONE, latency in frames 128.
mod.rs:2780: (0x7fd6d551eae0) Output hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
mod.rs:1351: The new buffer frames size of AudioUnit 0x8d26d070 for OUTPUT is 128
mod.rs:2885: (0x7fd6d551eae0) Output audiounit init with device 217 successfully.
mod.rs:2328: (0x7fd6d551eae0) Cubeb stream init successful.
stream_init succeed
state is CUBEB_STATE_STARTED
mod.rs:3598: Cubeb stream (0x7fd6d551eae0) started successfully.
stream_start succeed
press `q` to abort or `h` for help
mod.rs:562: (0x7fd6d551eae0) output: buffers 1, size 1024, channels 2, frames 128.
thread '<unnamed>' panicked at 'assertion failed: stm.switching_device.load(Ordering::SeqCst)', src/backend/mod.rs:647:25
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
fatal runtime error: Rust panics must be rethrown
Abort trap: 6
ChunMinChang commented 4 years ago

Thanks for the report!

https://github.com/ChunMinChang/cubeb-coreaudio-rs/blob/eff8fa32181c8c12452097f9c8784d630961da10/src/backend/mod.rs#L633-L655

Since this can happen without device-changing, so stm.frames_read.load(Ordering::SeqCst) == 0 is the case we enter that if-block. That means that the output-callnack comes before the input callback.

The reason for hitting that assertion is that stm.frames_read is increased right away upon entering that if-block:

stm.frames_read 
    .fetch_add(input_frames_needed, Ordering::SeqCst);

so if stm.frames_read.load(Ordering::SeqCst) == 0 is false in that cubeb_log! and stm.switching_device.load(Ordering::SeqCst) is false of course.

Moving 

stm.frames_read 
    .fetch_add(input_frames_needed, Ordering::SeqCst);

right after cubeb_log! should fix the crash.

Something like:

// The silent frames will be inserted in `get_linear_data` below.
cubeb_log!(
    "({:p}) Missing Frames: {} will append {} frames of input silence.",
    stm.core_stream_data.stm_ptr,
    if stm.frames_read.load(Ordering::SeqCst) == 0 {
        "input hasn't started,"
    } else {
        assert!(stm.switching_device.load(Ordering::SeqCst));
        "device switching,"
    },
    input_frames_needed - buffered_input_frames
);
stm.frames_read
    .fetch_add(input_frames_needed, Ordering::SeqCst);
input_frames_needed
achronop commented 4 years ago

Moving

stm.frames_read 
    .fetch_add(input_frames_needed, Ordering::SeqCst);

right after cubeb_log! should fix the crash.

@ChunMinChang thank you for looking at it. This is fixing it indeed but is it now the log outdated or the initial intention was to check&report before adding the input_frames_needed?

achronop commented 4 years ago

Just mentioning that I am able to reproduce it in Firefox with the same configuration of devices and the logs activated (MOZ_LOG=cubeb:4)


Data Source Item 2 - NullAudioDevice_ModelUID
Soundflower (2ch) - com_cycling74_driver_SoundflowerDevice:Soundflower
Soundflower (64ch) - com_cycling74_driver_SoundflowerDevice:Soundflower
Internal Microphone - builtin-internal-mic|spk
Plantronics .Audio 648 USB - Plantronics .Audio 648 USB:047F:C013
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:213: Creating a default device info.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:218: Requesting default system device.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2644: (0x169894400) Initialize output by device info: device_info { id: 213, flags: DEV_OUTPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2655: (0x169894400) Opening output side: rate 44100, channels 2, format Float32LE, layout FRONT_LEFT | FRONT_RIGHT, prefs NONE, latency in frames 128.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2693: (0x169894400) Output hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:1267: The new buffer frames size of AudioUnit 0x8de4506f for OUTPUT is 128
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2798: (0x169894400) Output audiounit init with device 213 successfully.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2244: (0x169894400) Cubeb stream init successful.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:3442: Cubeb stream (0x169894400) started successfully.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:3459: Cubeb stream (0x169894400) stopped successfully.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:3413: Cubeb stream (0x169894400) destroyed successful.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:218: Requesting default system device.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:213: Creating a default device info.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:218: Requesting default system device.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2508: (0x169894400) Initialize input by device info: device_info { id: 196, flags: DEV_INPUT | DEV_SYSTEM_DEFAULT }
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2519: (0x169894400) Opening input side: rate 44100, channels 2, format Float32LE, layout (empty), prefs VOICE, latency in frames 512.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2548: (0x169894400) Input hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:1196: The buffer frame size of AudioUnit 0x8de45070 for INPUT is already 512
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2636: (0x169894400) Input audiounit init with device 196 successfully.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2644: (0x169894400) Initialize output by device info: device_info { id: 213, flags: DEV_OUTPUT | DEV_SYSTEM_DEFAULT | DEV_SELECTED_DEFAULT }
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2655: (0x169894400) Opening output side: rate 44100, channels 2, format Float32LE, layout FRONT_LEFT | FRONT_RIGHT, prefs NONE, latency in frames 512.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2693: (0x169894400) Output hardware description: AudioStreamBasicDescription { mSampleRate: 44100.0, mFormatID: 1819304813, mFormatFlags: 9, mBytesPerPacket: 8, mFramesPerPacket: 1, mBytesPerFrame: 8, mChannelsPerFrame: 2, mBitsPerChannel: 32, mReserved: 0 }
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:1267: The new buffer frames size of AudioUnit 0x8de45071 for OUTPUT is 512
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2798: (0x169894400) Output audiounit init with device 213 successfully.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:2244: (0x169894400) Cubeb stream init successful.
[Child 56901: CubebOperation #1]: E/cubeb mod.rs:3442: Cubeb stream (0x169894400) started successfully.
Hit MOZ_CRASH(assertion failed: stm.switching_device.load(Ordering::SeqCst)) at /Users/achronopoulos/repos/mozilla/firefox/third_party/rust/cubeb-coreaudio/src/backend/mod.rs:647
ChunMinChang commented 4 years ago

@ChunMinChang thank you for looking at it. This is fixing it indeed but is it now the log outdated or the initial intention was to check&report before adding the input_frames_needed?

I don't think the log is necessary to be put after updatingstm.frames_read since the valud of stm.frames_read isn't used in the log, and the silent-frame would be inserted anyway (when get_linear_data is called).

Would you mind filing a PR to fix this?