sink, source: improve suspend cause logging

Previously the suspend cause was logged as a hexadecimal number, now
it's logged as a human-friendly string.

Also, the command line interface handled only a subset of causes when
printing them, now all suspend causes are printed.

src/pulsecore/cli-text.c

@@ -212,6 +212,7 @@ char *pa_sink_list_to_string(pa_core *c) {
             v[PA_VOLUME_SNPRINT_VERBOSE_MAX],
             cm[PA_CHANNEL_MAP_SNPRINT_MAX], *t;
         const char *cmn;
+        char suspend_cause_buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE];
 
         cmn = pa_channel_map_to_pretty_name(&sink->channel_map);
 
@@ -222,7 +223,7 @@ char *pa_sink_list_to_string(pa_core *c) {
             "\tdriver: <%s>\n"
             "\tflags: %s%s%s%s%s%s%s%s\n"
             "\tstate: %s\n"
-            "\tsuspend cause: %s%s%s%s\n"
+            "\tsuspend cause: %s\n"
             "\tpriority: %u\n"
             "\tvolume: %s\n"
             "\t        balance %0.2f\n"
@@ -250,10 +251,7 @@ char *pa_sink_list_to_string(pa_core *c) {
             sink->flags & PA_SINK_FLAT_VOLUME ? "FLAT_VOLUME " : "",
             sink->flags & PA_SINK_DYNAMIC_LATENCY ? "DYNAMIC_LATENCY" : "",
             pa_sink_state_to_string(pa_sink_get_state(sink)),
-            sink->suspend_cause & PA_SUSPEND_USER ? "USER " : "",
+            pa_suspend_cause_to_string(sink->suspend_cause, suspend_cause_buf),
-            sink->suspend_cause & PA_SUSPEND_APPLICATION ? "APPLICATION " : "",
-            sink->suspend_cause & PA_SUSPEND_IDLE ? "IDLE " : "",
-            sink->suspend_cause & PA_SUSPEND_SESSION ? "SESSION" : "",
             sink->priority,
             pa_cvolume_snprint_verbose(cv,
                                        sizeof(cv),
@@ -328,6 +326,7 @@ char *pa_source_list_to_string(pa_core *c) {
             v[PA_VOLUME_SNPRINT_VERBOSE_MAX],
             cm[PA_CHANNEL_MAP_SNPRINT_MAX], *t;
         const char *cmn;
+        char suspend_cause_buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE];
 
         cmn = pa_channel_map_to_pretty_name(&source->channel_map);
 
@@ -338,7 +337,7 @@ char *pa_source_list_to_string(pa_core *c) {
             "\tdriver: <%s>\n"
             "\tflags: %s%s%s%s%s%s%s\n"
             "\tstate: %s\n"
-            "\tsuspend cause: %s%s%s%s\n"
+            "\tsuspend cause: %s\n"
             "\tpriority: %u\n"
             "\tvolume: %s\n"
             "\t        balance %0.2f\n"
@@ -363,10 +362,7 @@ char *pa_source_list_to_string(pa_core *c) {
             source->flags & PA_SOURCE_LATENCY ? "LATENCY " : "",
             source->flags & PA_SOURCE_DYNAMIC_LATENCY ? "DYNAMIC_LATENCY" : "",
             pa_source_state_to_string(pa_source_get_state(source)),
-            source->suspend_cause & PA_SUSPEND_USER ? "USER " : "",
+            pa_suspend_cause_to_string(source->suspend_cause, suspend_cause_buf),
-            source->suspend_cause & PA_SUSPEND_APPLICATION ? "APPLICATION " : "",
-            source->suspend_cause & PA_SUSPEND_IDLE ? "IDLE " : "",
-            source->suspend_cause & PA_SUSPEND_SESSION ? "SESSION" : "",
             source->priority,
             pa_cvolume_snprint_verbose(cv,
                                        sizeof(cv),

src/pulsecore/core.c

@@ -502,3 +502,44 @@ void pa_core_rttime_restart(pa_core *c, pa_time_event *e, pa_usec_t usec) {
 
     c->mainloop->time_restart(e, pa_timeval_rtstore(&tv, usec, true));
 }
+
+/* Helper macro to reduce repetition in pa_suspend_cause_to_string().
+ * Parameters:
+ *   char *p: the current position in the write buffer
+ *   bool first: is cause_to_check the first cause to be written?
+ *   pa_suspend_cause_t cause_bitfield: the causes given to pa_suspend_cause_to_string()
+ *   pa_suspend_cause_t cause_to_check: the cause whose presence in cause_bitfield is to be checked
+ */
+#define CHECK_CAUSE(p, first, cause_bitfield, cause_to_check) \
+    if (cause_bitfield & PA_SUSPEND_##cause_to_check) {       \
+        size_t len = sizeof(#cause_to_check) - 1;             \
+        if (!first) {                                         \
+            *p = '|';                                         \
+            p++;                                              \
+        }                                                     \
+        first = false;                                        \
+        memcpy(p, #cause_to_check, len);                      \
+        p += len;                                             \
+    }
+
+const char *pa_suspend_cause_to_string(pa_suspend_cause_t cause_bitfield, char buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE]) {
+    char *p = buf;
+    bool first = true;
+
+    CHECK_CAUSE(p, first, cause_bitfield, USER);
+    CHECK_CAUSE(p, first, cause_bitfield, APPLICATION);
+    CHECK_CAUSE(p, first, cause_bitfield, IDLE);
+    CHECK_CAUSE(p, first, cause_bitfield, SESSION);
+    CHECK_CAUSE(p, first, cause_bitfield, PASSTHROUGH);
+    CHECK_CAUSE(p, first, cause_bitfield, INTERNAL);
+    CHECK_CAUSE(p, first, cause_bitfield, UNAVAILABLE);
+
+    if (p == buf) {
+        memcpy(p, "(none)", 6);
+        p += 6;
+    }
+
+    *p = 0;
+
+    return buf;
+}

src/pulsecore/core.h

@@ -26,7 +26,10 @@
 #include <pulsecore/cpu.h>
 
 /* This is a bitmask that encodes the cause why a sink/source is
- * suspended. */
+ * suspended.
+ *
+ * When adding new causes, remember to update pa_suspend_cause_to_string() and
+ * PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE! */
 typedef enum pa_suspend_cause {
     PA_SUSPEND_USER = 1,         /* Exposed to the user via some protocol */
     PA_SUSPEND_APPLICATION = 2,  /* Used by the device reservation logic */
@@ -266,4 +269,11 @@ void pa_core_maybe_vacuum(pa_core *c);
 pa_time_event* pa_core_rttime_new(pa_core *c, pa_usec_t usec, pa_time_event_cb_t cb, void *userdata);
 void pa_core_rttime_restart(pa_core *c, pa_time_event *e, pa_usec_t usec);
 
+static const size_t PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE =
+    sizeof("USER|APPLICATION|IDLE|SESSION|PASSTHROUGH|INTERNAL|UNAVAILABLE");
+
+/* Converts the given suspend cause to a string. The string is written to the
+ * provided buffer. The same buffer is the return value of this function. */
+const char *pa_suspend_cause_to_string(pa_suspend_cause_t cause, char buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE]);
+
 #endif

src/pulsecore/sink.c

@@ -840,11 +840,17 @@ void pa_sink_set_mixer_dirty(pa_sink *s, bool is_dirty) {
 
 /* Called from main context */
 int pa_sink_suspend(pa_sink *s, bool suspend, pa_suspend_cause_t cause) {
+    pa_suspend_cause_t old_cause;
+    char old_cause_buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE];
+    char new_cause_buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE];
+
     pa_sink_assert_ref(s);
     pa_assert_ctl_context();
     pa_assert(PA_SINK_IS_LINKED(s->state));
     pa_assert(cause != 0);
 
+    old_cause = s->suspend_cause;
+
     if (suspend) {
         s->suspend_cause |= cause;
         s->monitor_source->suspend_cause |= cause;
@@ -853,6 +859,11 @@ int pa_sink_suspend(pa_sink *s, bool suspend, pa_suspend_cause_t cause) {
         s->monitor_source->suspend_cause &= ~cause;
     }
 
+    if (s->suspend_cause != old_cause) {
+        pa_log_debug("%s: suspend_cause: %s -> %s", s->name, pa_suspend_cause_to_string(old_cause, old_cause_buf),
+                     pa_suspend_cause_to_string(s->suspend_cause, new_cause_buf));
+    }
+
     if (!(s->suspend_cause & PA_SUSPEND_SESSION) && (pa_atomic_load(&s->mixer_dirty) != 0)) {
         /* This might look racy but isn't: If somebody sets mixer_dirty exactly here,
            it'll be handled just fine. */
@@ -877,8 +888,6 @@ int pa_sink_suspend(pa_sink *s, bool suspend, pa_suspend_cause_t cause) {
     if ((pa_sink_get_state(s) == PA_SINK_SUSPENDED) == !!s->suspend_cause)
         return 0;
 
-    pa_log_debug("Suspend cause of sink %s is 0x%04x, %s", s->name, s->suspend_cause, s->suspend_cause ? "suspending" : "resuming");
-
     if (s->suspend_cause)
         return sink_set_state(s, PA_SINK_SUSPENDED);
     else

src/pulsecore/source.c

@@ -761,6 +761,10 @@ void pa_source_set_mixer_dirty(pa_source *s, bool is_dirty) {
 
 /* Called from main context */
 int pa_source_suspend(pa_source *s, bool suspend, pa_suspend_cause_t cause) {
+    pa_suspend_cause_t old_cause;
+    char old_cause_buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE];
+    char new_cause_buf[PA_SUSPEND_CAUSE_TO_STRING_BUF_SIZE];
+
     pa_source_assert_ref(s);
     pa_assert_ctl_context();
     pa_assert(PA_SOURCE_IS_LINKED(s->state));
@@ -769,11 +773,18 @@ int pa_source_suspend(pa_source *s, bool suspend, pa_suspend_cause_t cause) {
     if (s->monitor_of && cause != PA_SUSPEND_PASSTHROUGH)
         return -PA_ERR_NOTSUPPORTED;
 
+    old_cause = s->suspend_cause;
+
     if (suspend)
         s->suspend_cause |= cause;
     else
         s->suspend_cause &= ~cause;
 
+    if (s->suspend_cause != old_cause) {
+        pa_log_debug("%s: suspend_cause: %s -> %s", s->name, pa_suspend_cause_to_string(old_cause, old_cause_buf),
+                     pa_suspend_cause_to_string(s->suspend_cause, new_cause_buf));
+    }
+
     if (!(s->suspend_cause & PA_SUSPEND_SESSION) && (pa_atomic_load(&s->mixer_dirty) != 0)) {
         /* This might look racy but isn't: If somebody sets mixer_dirty exactly here,
            it'll be handled just fine. */
@@ -798,8 +809,6 @@ int pa_source_suspend(pa_source *s, bool suspend, pa_suspend_cause_t cause) {
     if ((pa_source_get_state(s) == PA_SOURCE_SUSPENDED) == !!s->suspend_cause)
         return 0;
 
-    pa_log_debug("Suspend cause of source %s is 0x%04x, %s", s->name, s->suspend_cause, s->suspend_cause ? "suspending" : "resuming");
-
     if (s->suspend_cause)
         return source_set_state(s, PA_SOURCE_SUSPENDED);
     else