Audio Mic Record Demo fails to record when debug/settings/stdout/verbose_stdout=true on Linux

[goatchurchprime]

Tested versions

This problem appears in v4.4.beta1 (not in v4.4.dev7).

System information

Godot v4.4.beta (77dcf97) - NixOS #​1-NixOS SMP PREEMPT_DYNAMIC Thu Sep 12 09:13:13 UTC 2024 on X11 - X11 display driver, Multi-window, 1 monitor - OpenGL 3 (Compatibility) - Mesa Intel(R) Graphics (ADL GT2) - 12th Gen Intel(R) Core(TM) i5-1240P (16 threads)

Issue description

The suspect PR which changed some behavior of the Microphone stream was noted by me here: #101097 (comment)

What changed was that if you called play() on an already playing AudioStreamPlayer with an AudioStreamMicrophone on Linux (okay on Windows) the microphone stopped working and gave out the error:

ERROR: PulseAudio: pa_stream_disconnect error: Bad state

This is probably due to the bug that allows multiple calls to the singular AudioDriver::input_start() (Item 1 of #100508 )

The above is just context.

This bug is about the microphone no longer working when you enable debug/settings/stdout/verbose_stdout in Linux. I have no idea how this could be.

Steps to reproduce

Run the demo project. https://github.com/godotengine/godot-demo-projects/tree/master/audio/mic_record

Click Record, say something, click Stop, then click Play to hear it back.

Now under Project Settings -> Debug -> Settings, enable Verbose stdout, and repeat.

Aside from now playing no sound, my output is:

CameraServer: Registered camera Laptop Camera: Laptop Camera with ID 1 and position 0 at index 0
Loading resource: res://default_bus_layout.tres
CORE API HASH: 3420400551
EDITOR API HASH: 33618999
Loaded system CA certificates
Loading resource: res://MicRecord.tscn
Loading resource: res://MicRecord.gd
Loading resource: res://Intro.ogg
Loading resource: res://.godot/imported/Intro.ogg-dfe75727d0e47692e220adf97ddb7ad9.oggvorbisstr
PulseAudio: Detecting channels for device: alsa_input.pci-0000_00_1f.3.analog-stereo
PulseAudio: detected 2 input channels
PulseAudio: detected 2 input channels
PulseAudio: input buffer frames: 1024 calculated latency: 23ms

Playing recording: <AudioStreamWAV#-9223372001740061239>
Format: 16-bit uncompressed
Mix rate: 44100 Hz
Stereo: Yes
Size: 159744 bytes

The suspicious duplication of the "detected 2 input channels" message is merely the statement appearing twice in the function.
https://github.com/godotengine/godot/blob/master/drivers/pulseaudio/audio_driver_pulseaudio.cpp#L716

Minimal reproduction project (MRP)

see above

[Calinou]

What's interesting is that people used to fix audio recording in the 3.x days by enabling verbose output. I suspect some subtle timing issue in here.

[goatchurchprime]

Using my PR #100508 that pulls the samples from the microphone input buffer at only the rate they are generated (instead of packing zeros into the stream when there aren't enough, or stopping the stream all together), I measure 360 samples per second instead of approx 44000 samples per second. The linking cycle is pretty slow on my laptop, but all I can think of doing is hacking away some of these verbose print statements to see when it makes a difference.

[goatchurchprime]

The problem replicates on another Linux/Nixos laptop of a different brand. After many recompilations I've found it works (ie records with and without debug/settings/stdout/verbose_stdout=true) on my main laptop when I delete all three print_verbose() lines of the function AudioDriverPulseAudio::init_input_device().

If you delete only the first print_verbose() on line 716 then nothing works, not even when verbose_stdout=false. I've been here before, with the microphone on Linux seeming to break on revisions that appear to make no change to the audio system. It's just unexplained whether a build works or doesn't.

I have begun interrogating and logging the state of the pa_rec_str stream initialized by pa_stream_connect_record() using a stream_state_callback().

When the stream is good the callback report is:

Stream successfully created.
Buffer metrics: maxlength=4194304, fragsize=4096
Using sample spec 's16le 2ch 44100Hz', channel map 'front-left,front-right'.
Connected to device alsa_input.pci-0000_00_1f.3.analog-stereo (55, not suspended).

When the input stream fails to work the callback report is:

Stream successfully created.
Buffer metrics: maxlength=16, fragsize=4
Using sample spec 's16le 2ch 44100Hz', channel map 'front-left,front-right'.
Connected to device alsa_input.pci-0000_00_1f.3.analog-stereo (55, not suspended).

[goatchurchprime]

I've inserted many more print statements and it looks like the attr.maxlength is set to a random uninitialized value, depending on how things get compiled. When the value is huge you get a 4Mb buffer, and when it is small the buffer is too constrained to work.

This explains everything, and why it has been intermittently failing for years.

The documentation for pa_buffer_attr recommends setting it to (uint32_t)-1.