[PATCH 18/43] audio/alsa: replace custom logging with error_report and trace events

marcandre.lureau@redhat.com posted 43 patches 1 week, 6 days ago
Maintainers: Gerd Hoffmann <kraxel@redhat.com>, Christian Schoenebeck <qemu_oss@crudebyte.com>, "Marc-André Lureau" <marcandre.lureau@redhat.com>, "Philippe Mathieu-Daudé" <philmd@linaro.org>, Akihiko Odaki <odaki@rsg.ci.i.u-tokyo.ac.jp>, Thomas Huth <huth@tuxfamily.org>, Alexandre Ratchov <alex@caoua.org>, Laurent Vivier <laurent@vivier.eu>, Manos Pitsidianakis <manos.pitsidianakis@linaro.org>, "Michael S. Tsirkin" <mst@redhat.com>, Alistair Francis <alistair@alistair23.me>, "Edgar E. Iglesias" <edgar.iglesias@gmail.com>, Peter Maydell <peter.maydell@linaro.org>
[PATCH 18/43] audio/alsa: replace custom logging with error_report and trace events
Posted by marcandre.lureau@redhat.com 1 week, 6 days ago
From: Marc-André Lureau <marcandre.lureau@redhat.com>

The ALSA audio backend uses its own logging infrastructure (AUD_log,
AUD_vlog, dolog, ldebug) and a custom alsa_dump_info() debug helper.
This approach is inconsistent with the rest of QEMU and makes the
output harder to filter and configure.

Replace the custom logging with standard QEMU error reporting:
- Use error_report() / error_printf() for errors
- Use warn_report() for non-fatal warnings (invalid formats,
  rejected parameters, unexpected states)
- Convert ldebug() calls and alsa_dump_info() to trace events

Remove DEBUG_ALSA and AUDIO_CAP macros which are no longer needed.

Signed-off-by: Marc-André Lureau <marcandre.lureau@redhat.com>
---
 audio/alsaaudio.c  | 169 ++++++++++++++++++---------------------------
 audio/trace-events |   5 ++
 2 files changed, 72 insertions(+), 102 deletions(-)

diff --git a/audio/alsaaudio.c b/audio/alsaaudio.c
index d3697a148da..3058af58e0b 100644
--- a/audio/alsaaudio.c
+++ b/audio/alsaaudio.c
@@ -26,17 +26,15 @@
 #include <alsa/asoundlib.h>
 #include "qemu/main-loop.h"
 #include "qemu/module.h"
+#include "qemu/error-report.h"
 #include "qemu/audio.h"
 #include "qom/object.h"
 #include "trace.h"
 
 #pragma GCC diagnostic ignored "-Waddress"
 
-#define AUDIO_CAP "alsa"
 #include "audio_int.h"
 
-#define DEBUG_ALSA 0
-
 #define TYPE_AUDIO_ALSA "audio-alsa"
 OBJECT_DECLARE_SIMPLE_TYPE(AudioALSA, AUDIO_ALSA)
 
@@ -81,33 +79,29 @@ struct alsa_params_obt {
     snd_pcm_uframes_t samples;
 };
 
-static void G_GNUC_PRINTF (2, 3) alsa_logerr (int err, const char *fmt, ...)
+static void G_GNUC_PRINTF(2, 3) alsa_logerr(int err, const char *fmt, ...)
 {
     va_list ap;
 
-    va_start (ap, fmt);
-    AUD_vlog (AUDIO_CAP, fmt, ap);
-    va_end (ap);
-
-    AUD_log (AUDIO_CAP, "Reason: %s\n", snd_strerror (err));
+    error_printf("alsa: ");
+    va_start(ap, fmt);
+    error_vprintf(fmt, ap);
+    va_end(ap);
+    error_printf(" Reason: %s", snd_strerror(err));
+    error_printf("\n");
 }
 
-static void G_GNUC_PRINTF (3, 4) alsa_logerr2 (
-    int err,
-    const char *typ,
-    const char *fmt,
-    ...
-    )
+static void G_GNUC_PRINTF(3, 4) alsa_logerr2(int err, const char *typ,
+                                             const char *fmt, ...)
 {
     va_list ap;
 
-    AUD_log (AUDIO_CAP, "Could not initialize %s\n", typ);
-
-    va_start (ap, fmt);
-    AUD_vlog (AUDIO_CAP, fmt, ap);
-    va_end (ap);
-
-    AUD_log (AUDIO_CAP, "Reason: %s\n", snd_strerror (err));
+    error_printf("alsa: Could not initialize %s:", typ);
+    va_start(ap, fmt);
+    error_vprintf(fmt, ap);
+    va_end(ap);
+    error_printf(" Reason: %s", snd_strerror(err));
+    error_printf("\n");
 }
 
 static void alsa_fini_poll (struct pollhlp *hlp)
@@ -130,7 +124,7 @@ static void alsa_anal_close1 (snd_pcm_t **handlep)
 {
     int err = snd_pcm_close (*handlep);
     if (err) {
-        alsa_logerr (err, "Failed to close PCM handle %p\n", *handlep);
+        alsa_logerr(err, "Failed to close PCM handle %p", *handlep);
     }
     *handlep = NULL;
 }
@@ -145,7 +139,7 @@ static int alsa_recover (snd_pcm_t *handle)
 {
     int err = snd_pcm_prepare (handle);
     if (err < 0) {
-        alsa_logerr (err, "Failed to prepare handle %p\n", handle);
+        alsa_logerr(err, "Failed to prepare handle %p", handle);
         return -1;
     }
     return 0;
@@ -155,7 +149,7 @@ static int alsa_resume (snd_pcm_t *handle)
 {
     int err = snd_pcm_resume (handle);
     if (err < 0) {
-        alsa_logerr (err, "Failed to resume handle %p\n", handle);
+        alsa_logerr(err, "Failed to resume handle %p", handle);
         return -1;
     }
     return 0;
@@ -170,7 +164,7 @@ static void alsa_poll_handler (void *opaque)
 
     count = poll (hlp->pfds, hlp->count, 0);
     if (count < 0) {
-        dolog ("alsa_poll_handler: poll %s\n", strerror (errno));
+        warn_report("alsa_poll_handler: poll %s", strerror(errno));
         return;
     }
 
@@ -183,7 +177,7 @@ static void alsa_poll_handler (void *opaque)
     err = snd_pcm_poll_descriptors_revents (hlp->handle, hlp->pfds,
                                             hlp->count, &revents);
     if (err < 0) {
-        alsa_logerr (err, "snd_pcm_poll_descriptors_revents");
+        alsa_logerr(err, "snd_pcm_poll_descriptors_revents");
         return;
     }
 
@@ -215,7 +209,7 @@ static void alsa_poll_handler (void *opaque)
         break;
 
     default:
-        dolog ("Unexpected state %d\n", state);
+        warn_report("alsa: Unexpected state %d", state);
     }
 }
 
@@ -226,8 +220,8 @@ static int alsa_poll_helper (snd_pcm_t *handle, struct pollhlp *hlp, int mask)
 
     count = snd_pcm_poll_descriptors_count (handle);
     if (count <= 0) {
-        dolog ("Could not initialize poll mode\n"
-               "Invalid number of poll descriptors %d\n", count);
+        warn_report("alsa: Could not initialize poll mode: "
+                    "Invalid number of poll descriptors %d", count);
         return -1;
     }
 
@@ -235,8 +229,7 @@ static int alsa_poll_helper (snd_pcm_t *handle, struct pollhlp *hlp, int mask)
 
     err = snd_pcm_poll_descriptors (handle, pfds, count);
     if (err < 0) {
-        alsa_logerr (err, "Could not initialize poll mode\n"
-                     "Could not obtain poll descriptors\n");
+        alsa_logerr(err, "Could not initialize poll mode: Could not obtain poll descriptors");
         g_free (pfds);
         return -1;
     }
@@ -298,10 +291,7 @@ static snd_pcm_format_t aud_to_alsafmt(AudioFormat fmt, bool big_endian)
         return big_endian ? SND_PCM_FORMAT_FLOAT_BE : SND_PCM_FORMAT_FLOAT_LE;
 
     default:
-        dolog ("Internal logic error: Bad audio format %d\n", fmt);
-#ifdef DEBUG_AUDIO
-        abort ();
-#endif
+        warn_report("alsa: Internal logic error: Bad audio format %d", fmt);
         return SND_PCM_FORMAT_U8;
     }
 }
@@ -371,29 +361,13 @@ static int alsa_to_audfmt (snd_pcm_format_t alsafmt, AudioFormat *fmt,
         break;
 
     default:
-        dolog ("Unrecognized audio format %d\n", alsafmt);
+        warn_report("alsa: Unrecognized audio format %d", alsafmt);
         return -1;
     }
 
     return 0;
 }
 
-static void alsa_dump_info (struct alsa_params_req *req,
-                            struct alsa_params_obt *obt,
-                            snd_pcm_format_t obtfmt,
-                            AudiodevAlsaPerDirectionOptions *apdo)
-{
-    dolog("parameter | requested value | obtained value\n");
-    dolog("format    |      %10d |     %10d\n", req->fmt, obtfmt);
-    dolog("channels  |      %10d |     %10d\n",
-          req->nchannels, obt->nchannels);
-    dolog("frequency |      %10d |     %10d\n", req->freq, obt->freq);
-    dolog("============================================\n");
-    dolog("requested: buffer len %" PRId32 " period len %" PRId32 "\n",
-          apdo->buffer_length, apdo->period_length);
-    dolog("obtained: samples %ld\n", obt->samples);
-}
-
 static void alsa_set_threshold (snd_pcm_t *handle, snd_pcm_uframes_t threshold)
 {
     int err;
@@ -403,23 +377,22 @@ static void alsa_set_threshold (snd_pcm_t *handle, snd_pcm_uframes_t threshold)
 
     err = snd_pcm_sw_params_current (handle, sw_params);
     if (err < 0) {
-        dolog ("Could not fully initialize DAC\n");
-        alsa_logerr (err, "Failed to get current software parameters\n");
+        error_report("alsa: Could not fully initialize DAC");
+        alsa_logerr(err, "Failed to get current software parameters");
         return;
     }
 
     err = snd_pcm_sw_params_set_start_threshold (handle, sw_params, threshold);
     if (err < 0) {
-        dolog ("Could not fully initialize DAC\n");
-        alsa_logerr (err, "Failed to set software threshold to %ld\n",
-                     threshold);
+        error_report("alsa: Could not fully initialize DAC");
+        alsa_logerr(err, "Failed to set software threshold to %ld", threshold);
         return;
     }
 
     err = snd_pcm_sw_params (handle, sw_params);
     if (err < 0) {
-        dolog ("Could not fully initialize DAC\n");
-        alsa_logerr (err, "Failed to set software parameters\n");
+        error_report("alsa: Could not fully initialize DAC");
+        alsa_logerr(err, "Failed to set software parameters");
         return;
     }
 }
@@ -451,13 +424,13 @@ static int alsa_open(bool in, struct alsa_params_req *req,
         SND_PCM_NONBLOCK
         );
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to open `%s':\n", pcm_name);
+        alsa_logerr2(err, typ, "Failed to open `%s'", pcm_name);
         return -1;
     }
 
     err = snd_pcm_hw_params_any (handle, hw_params);
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to initialize hardware parameters\n");
+        alsa_logerr2(err, typ, "Failed to initialize hardware parameters");
         goto err;
     }
 
@@ -467,18 +440,18 @@ static int alsa_open(bool in, struct alsa_params_req *req,
         SND_PCM_ACCESS_RW_INTERLEAVED
         );
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to set access type\n");
+        alsa_logerr2(err, typ, "Failed to set access type");
         goto err;
     }
 
     err = snd_pcm_hw_params_set_format (handle, hw_params, req->fmt);
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to set format %d\n", req->fmt);
+        alsa_logerr2(err, typ, "Failed to set format %d", req->fmt);
     }
 
     err = snd_pcm_hw_params_set_rate_near (handle, hw_params, &freq, 0);
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to set frequency %d\n", req->freq);
+        alsa_logerr2(err, typ, "Failed to set frequency %d", req->freq);
         goto err;
     }
 
@@ -488,8 +461,7 @@ static int alsa_open(bool in, struct alsa_params_req *req,
         &nchannels
         );
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to set number of channels %d\n",
-                      req->nchannels);
+        alsa_logerr2(err, typ, "Failed to set number of channels %d", req->nchannels);
         goto err;
     }
 
@@ -501,14 +473,14 @@ static int alsa_open(bool in, struct alsa_params_req *req,
             handle, hw_params, &btime, &dir);
 
         if (err < 0) {
-            alsa_logerr2(err, typ, "Failed to set buffer time to %" PRId32 "\n",
+            alsa_logerr2(err, typ, "Failed to set buffer time to %" PRId32,
                          apdo->buffer_length);
             goto err;
         }
 
         if (apdo->has_buffer_length && btime != apdo->buffer_length) {
-            dolog("Requested buffer time %" PRId32
-                  " was rejected, using %u\n", apdo->buffer_length, btime);
+            warn_report("alsa: Requested buffer time %" PRId32 " was rejected, using %u",
+                        apdo->buffer_length, btime);
         }
     }
 
@@ -520,43 +492,43 @@ static int alsa_open(bool in, struct alsa_params_req *req,
                                                      &dir);
 
         if (err < 0) {
-            alsa_logerr2(err, typ, "Failed to set period time to %" PRId32 "\n",
+            alsa_logerr2(err, typ, "Failed to set period time to %" PRId32,
                          apdo->period_length);
             goto err;
         }
 
         if (apdo->has_period_length && ptime != apdo->period_length) {
-            dolog("Requested period time %" PRId32 " was rejected, using %d\n",
-                  apdo->period_length, ptime);
+            warn_report("alsa: Requested period time %" PRId32 " was rejected, using %d",
+                        apdo->period_length, ptime);
         }
     }
 
     err = snd_pcm_hw_params (handle, hw_params);
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to apply audio parameters\n");
+        alsa_logerr2(err, typ, "Failed to apply audio parameters");
         goto err;
     }
 
     err = snd_pcm_hw_params_get_buffer_size (hw_params, &obt_buffer_size);
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to get buffer size\n");
+        alsa_logerr2(err, typ, "Failed to get buffer size");
         goto err;
     }
 
     err = snd_pcm_hw_params_get_format (hw_params, &obtfmt);
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Failed to get format\n");
+        alsa_logerr2(err, typ, "Failed to get format");
         goto err;
     }
 
     if (alsa_to_audfmt (obtfmt, &obt->fmt, &obt->endianness)) {
-        dolog ("Invalid format was returned %d\n", obtfmt);
+        error_report("alsa: Invalid format was returned %d", obtfmt);
         goto err;
     }
 
     err = snd_pcm_prepare (handle);
     if (err < 0) {
-        alsa_logerr2 (err, typ, "Could not prepare handle %p\n", handle);
+        alsa_logerr2(err, typ, "Could not prepare handle %p", handle);
         goto err;
     }
 
@@ -574,11 +546,9 @@ static int alsa_open(bool in, struct alsa_params_req *req,
 
     *handlep = handle;
 
-    if (DEBUG_ALSA || obtfmt != req->fmt ||
-        obt->nchannels != req->nchannels || obt->freq != req->freq) {
-        dolog ("Audio parameters for %s\n", typ);
-        alsa_dump_info(req, obt, obtfmt, apdo);
-    }
+    trace_alsa_info_params(req->fmt, obtfmt, req->nchannels, obt->nchannels,
+                           req->freq, obt->freq);
+    trace_alsa_info_samples(apdo->buffer_length, apdo->period_length, obt->samples);
 
     return 0;
 
@@ -601,8 +571,7 @@ static size_t alsa_buffer_get_free(HWVoiceOut *hw)
             }
         }
         if (avail < 0) {
-            alsa_logerr(avail,
-                        "Could not obtain number of available frames\n");
+            alsa_logerr(avail, "Could not obtain number of available frames");
             avail = 0;
         }
     }
@@ -643,8 +612,7 @@ static size_t alsa_write(HWVoiceOut *hw, void *buf, size_t len)
 
             case -EPIPE:
                 if (alsa_recover(alsa->handle)) {
-                    alsa_logerr(written, "Failed to write %zu frames\n",
-                                len_frames);
+                    alsa_logerr(written, "Failed to write %zu frames", len_frames);
                     return pos;
                 }
                 trace_alsa_xrun_out();
@@ -656,8 +624,7 @@ static size_t alsa_write(HWVoiceOut *hw, void *buf, size_t len)
                  * recovery
                  */
                 if (alsa_resume(alsa->handle)) {
-                    alsa_logerr(written, "Failed to write %zu frames\n",
-                                len_frames);
+                    alsa_logerr(written, "Failed to write %zu frames", len_frames);
                     return pos;
                 }
                 trace_alsa_resume_out();
@@ -667,8 +634,7 @@ static size_t alsa_write(HWVoiceOut *hw, void *buf, size_t len)
                 return pos;
 
             default:
-                alsa_logerr(written, "Failed to write %zu frames from %p\n",
-                            len, src);
+                alsa_logerr(written, "Failed to write %zu frames from %p", len_frames, src);
                 return pos;
             }
         }
@@ -687,7 +653,7 @@ static void alsa_fini_out (HWVoiceOut *hw)
 {
     ALSAVoiceOut *alsa = (ALSAVoiceOut *) hw;
 
-    ldebug ("alsa_fini\n");
+    trace_alsa_fini_out();
     alsa_anal_close (&alsa->handle, &alsa->pollhlp);
 }
 
@@ -732,19 +698,19 @@ static int alsa_voice_ctl (snd_pcm_t *handle, const char *typ, int ctl)
     if (ctl == VOICE_CTL_PAUSE) {
         err = snd_pcm_drop (handle);
         if (err < 0) {
-            alsa_logerr (err, "Could not stop %s\n", typ);
+            alsa_logerr(err, "Could not stop %s", typ);
             return -1;
         }
     } else {
         err = snd_pcm_prepare (handle);
         if (err < 0) {
-            alsa_logerr (err, "Could not prepare handle for %s\n", typ);
+            alsa_logerr(err, "Could not prepare handle for %s", typ);
             return -1;
         }
         if (ctl == VOICE_CTL_START) {
             err = snd_pcm_start(handle);
             if (err < 0) {
-                alsa_logerr (err, "Could not start handle for %s\n", typ);
+                alsa_logerr(err, "Could not start handle for %s", typ);
                 return -1;
             }
         }
@@ -758,17 +724,17 @@ static void alsa_enable_out(HWVoiceOut *hw, bool enable)
     ALSAVoiceOut *alsa = (ALSAVoiceOut *) hw;
     AudiodevAlsaPerDirectionOptions *apdo = hw->s->dev->u.alsa.out;
 
+    trace_alsa_enable_out(enable);
+
     if (enable) {
         bool poll_mode = apdo->try_poll;
 
-        ldebug("enabling voice\n");
         if (poll_mode && alsa_poll_out(hw)) {
             poll_mode = 0;
         }
         hw->poll_mode = poll_mode;
         alsa_voice_ctl(alsa->handle, "playback", VOICE_CTL_PREPARE);
     } else {
-        ldebug("disabling voice\n");
         if (hw->poll_mode) {
             hw->poll_mode = 0;
             alsa_fini_poll(&alsa->pollhlp);
@@ -834,7 +800,7 @@ static size_t alsa_read(HWVoiceIn *hw, void *buf, size_t len)
 
             case -EPIPE:
                 if (alsa_recover(alsa->handle)) {
-                    alsa_logerr(nread, "Failed to read %zu frames\n", len);
+                    alsa_logerr(nread, "Failed to read %zu frames", len);
                     return pos;
                 }
                 trace_alsa_xrun_in();
@@ -844,8 +810,7 @@ static size_t alsa_read(HWVoiceIn *hw, void *buf, size_t len)
                 return pos;
 
             default:
-                alsa_logerr(nread, "Failed to read %zu frames to %p\n",
-                            len, dst);
+                alsa_logerr(nread, "Failed to read %zu frames to %p", len, dst);
                 return pos;
             }
         }
@@ -862,10 +827,11 @@ static void alsa_enable_in(HWVoiceIn *hw, bool enable)
     ALSAVoiceIn *alsa = (ALSAVoiceIn *) hw;
     AudiodevAlsaPerDirectionOptions *apdo = hw->s->dev->u.alsa.in;
 
+    trace_alsa_enable_in(enable);
+
     if (enable) {
         bool poll_mode = apdo->try_poll;
 
-        ldebug("enabling voice\n");
         if (poll_mode && alsa_poll_in(hw)) {
             poll_mode = 0;
         }
@@ -873,7 +839,6 @@ static void alsa_enable_in(HWVoiceIn *hw, bool enable)
 
         alsa_voice_ctl(alsa->handle, "capture", VOICE_CTL_START);
     } else {
-        ldebug ("disabling voice\n");
         if (hw->poll_mode) {
             hw->poll_mode = 0;
             alsa_fini_poll(&alsa->pollhlp);
diff --git a/audio/trace-events b/audio/trace-events
index f7f639d9605..737e3e60694 100644
--- a/audio/trace-events
+++ b/audio/trace-events
@@ -9,6 +9,11 @@ alsa_read_zero(long len) "Failed to read %ld frames (read zero)"
 alsa_xrun_out(void) "Recovering from playback xrun"
 alsa_xrun_in(void) "Recovering from capture xrun"
 alsa_resume_out(void) "Resuming suspended output stream"
+alsa_info_params(int req_fmt, int obt_fmt, int req_channels, int obt_channels, int req_freq, int obt_freq) "format %d->%d, channels %d->%d, frequency %d->%d"
+alsa_info_samples(int buffer_length, int period_length, long samples) "requested: buffer len %d, period len %d; obtained: %ld samples"
+alsa_fini_out(void) ""
+alsa_enable_out(bool enable) "enable=%d"
+alsa_enable_in(bool enable) "enable=%d"
 
 # ossaudio.c
 oss_version(int version) "OSS version = 0x%x"
-- 
2.52.0