audio: Add some formal debug logging to device open/close attempts.

src/audio/SDL_audio.c

@@ -112,6 +112,15 @@ static SDL_AudioDriver current_audio;
 // Deduplicated list of audio bootstrap drivers.
 static const AudioBootStrap *deduped_bootstrap[SDL_arraysize(bootstrap) - 1];
 
+static const char *GetShortAudioFormatName(SDL_AudioFormat fmt)
+{
+    const char *fmtstr = SDL_GetAudioFormatName(fmt);
+    if (fmtstr) {
+        fmtstr += 10;  // skip "SDL_AUDIO_"
+    }
+    return fmtstr;
+}
+
 int SDL_GetNumAudioDrivers(void)
 {
     static int num_drivers = -1;
@@ -1735,8 +1744,15 @@ static void SerializePhysicalDeviceClose(SDL_AudioDevice *device)
 // this expects the device lock to be held.
 static void ClosePhysicalAudioDevice(SDL_AudioDevice *device)
 {
+    SDL_assert(device != NULL);
+
     SerializePhysicalDeviceClose(device);
 
+    if (device->currently_opened) {  // there might be other cleanup even when closed, but only log this if we were fully up and running.
+        const char *devtypestr = device->recording ? "recording" : "playback";
+        SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: closing %s device '%s'", devtypestr, device->name);
+    }
+
     SDL_SetAtomicInt(&device->shutdown, 1);
 
     // YOU MUST PROTECT KEY POINTS WITH SerializePhysicalDeviceClose() WHILE THE THREAD JOINS
@@ -1867,6 +1883,8 @@ static bool OpenPhysicalAudioDevice(SDL_AudioDevice *device, const SDL_AudioSpec
         return true;  // Braaaaaaaaains.
     }
 
+    const char *devtypestr = device->recording ? "recording" : "playback";
+
     SDL_AudioSpec spec;
     SDL_copyp(&spec, inspec ? inspec : &device->default_spec);
     PrepareAudioFormat(device->recording, &spec);
@@ -1889,7 +1907,7 @@ static bool OpenPhysicalAudioDevice(SDL_AudioDevice *device, const SDL_AudioSpec
         spec.channels = SDL_max(spec.channels, current.channels);
         spec.freq = SDL_max(spec.freq, current.freq);
 
-        SDL_Log("AUDIO: attempt to reopen device '%s' at higher spec! (%s,%d,%d => %s,%d,%d)", device->name, SDL_GetAudioFormatName(current.format), current.channels, current.freq, SDL_GetAudioFormatName(spec.format), spec.channels, spec.freq);
+        SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: attempt to reopen %s device '%s' at higher spec! (%s,%d,%d => %s,%d,%d)", devtypestr, device->name, GetShortAudioFormatName(current.format), current.channels, current.freq, GetShortAudioFormatName(spec.format), spec.channels, spec.freq);
         ClosePhysicalAudioDevice(device);
         if (!OpenPhysicalAudioDevice(device, &spec)) {
             // no good, try to go back to our original spec...
@@ -1906,6 +1924,8 @@ static bool OpenPhysicalAudioDevice(SDL_AudioDevice *device, const SDL_AudioSpec
         SDL_copyp(&device->spec, &current);  // put it back to what it was so the next function call doesn't return immediately. The next call will reset it properly.
         SDL_AudioDeviceFormatChangedAlreadyLocked(device, &spec, device->sample_frames);  // if this fails, it's probably because we're out of memory and didn't send the events, but the device is _probably_ functional!
 
+        SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: %s device '%s' is now at spec (%s,%d,%d)", devtypestr, device->name, GetShortAudioFormatName(device->spec.format), device->spec.channels, device->spec.freq);
+
         return true;  // carry on with the reconfigured device!
     }
 
@@ -1920,8 +1940,11 @@ static bool OpenPhysicalAudioDevice(SDL_AudioDevice *device, const SDL_AudioSpec
     device->sample_frames = SDL_GetDefaultSampleFramesFromFreq(device->spec.freq);
     SDL_UpdatedAudioDeviceFormat(device);  // start this off sane.
 
+    SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: attempt to open %s device '%s' at spec (%s,%d,%d)", devtypestr, device->name, GetShortAudioFormatName(spec.format), spec.channels, spec.freq);
+
     device->currently_opened = true;  // mark this true even if impl.OpenDevice fails, so we know to clean up.
     if (!current_audio.impl.OpenDevice(device)) {
+        SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: open of %s device '%s' failed: %s", devtypestr, device->name, SDL_GetError());
         ClosePhysicalAudioDevice(device);  // clean up anything the backend left half-initialized.
         return false;
     }
@@ -1931,6 +1954,7 @@ static bool OpenPhysicalAudioDevice(SDL_AudioDevice *device, const SDL_AudioSpec
     // Allocate a scratch audio buffer
     device->work_buffer = (Uint8 *)SDL_aligned_alloc(SDL_GetSIMDAlignment(), device->work_buffer_size);
     if (!device->work_buffer) {
+        SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: open of %s device '%s' failed: %s", devtypestr, device->name, SDL_GetError());
         ClosePhysicalAudioDevice(device);
         return false;
     }
@@ -1938,6 +1962,7 @@ static bool OpenPhysicalAudioDevice(SDL_AudioDevice *device, const SDL_AudioSpec
     if (device->spec.format != SDL_AUDIO_F32) {
         device->mix_buffer = (Uint8 *)SDL_aligned_alloc(SDL_GetSIMDAlignment(), device->work_buffer_size);
         if (!device->mix_buffer) {
+            SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: open of %s device '%s' failed: %s", devtypestr, device->name, SDL_GetError());
             ClosePhysicalAudioDevice(device);
             return false;
         }
@@ -1950,11 +1975,14 @@ static bool OpenPhysicalAudioDevice(SDL_AudioDevice *device, const SDL_AudioSpec
         device->thread = SDL_CreateThread(device->recording ? RecordingAudioThread : PlaybackAudioThread, threadname, device);
 
         if (!device->thread) {
+            SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: open of %s device '%s' failed: %s", devtypestr, device->name, SDL_GetError());
             ClosePhysicalAudioDevice(device);
             return SDL_SetError("Couldn't create audio thread");
         }
     }
 
+    SDL_LogDebug(SDL_LOG_CATEGORY_AUDIO, "AUDIO: attempt to open %s device '%s' succeeded! Opened at spec (%s,%d,%d)", devtypestr, device->name, GetShortAudioFormatName(device->spec.format), device->spec.channels, device->spec.freq);
+
     return true;
 }