Log the reason for every suspend/resume.

I was looking at a log that showed that a suspend happened (at
a strange time), but the log didn't tell me why the suspend was done.
This patch tries to make sure that that won't happen again.

src/modules/alsa/alsa-sink.c

@@ -173,6 +173,8 @@ static pa_hook_result_t reserve_cb(pa_reserve_wrapper *r, void *forced, struct u
     pa_assert(r);
     pa_assert(u);
 
+    pa_log_debug("Suspending sink %s, because another application requested us to release the device.", u->sink->name);
+
     if (pa_sink_suspend(u->sink, TRUE, PA_SUSPEND_APPLICATION) < 0)
         return PA_HOOK_CANCEL;
 
@@ -235,14 +237,17 @@ static int reserve_init(struct userdata *u, const char *dname) {
 }
 
 static pa_hook_result_t monitor_cb(pa_reserve_monitor_wrapper *w, void* busy, struct userdata *u) {
-    pa_bool_t b;
-
     pa_assert(w);
     pa_assert(u);
 
-    b = PA_PTR_TO_UINT(busy) && !u->reserve;
+    if (PA_PTR_TO_UINT(busy) && !u->reserve) {
+        pa_log_debug("Suspending sink %s, because another application is blocking the access to the device.", u->sink->name);
+        pa_sink_suspend(u->sink, true, PA_SUSPEND_APPLICATION);
+    } else {
+        pa_log_debug("Resuming sink %s, because other applications aren't blocking access to the device any more.", u->sink->name);
+        pa_sink_suspend(u->sink, false, PA_SUSPEND_APPLICATION);
+    }
 
-    pa_sink_suspend(u->sink, b, PA_SUSPEND_APPLICATION);
     return PA_HOOK_OK;
 }
 

src/modules/alsa/alsa-source.c

@@ -148,6 +148,8 @@ static pa_hook_result_t reserve_cb(pa_reserve_wrapper *r, void *forced, struct u
     pa_assert(r);
     pa_assert(u);
 
+    pa_log_debug("Suspending source %s, because another application requested us to release the device.", u->source->name);
+
     if (pa_source_suspend(u->source, TRUE, PA_SUSPEND_APPLICATION) < 0)
         return PA_HOOK_CANCEL;
 
@@ -210,14 +212,17 @@ static int reserve_init(struct userdata *u, const char *dname) {
 }
 
 static pa_hook_result_t monitor_cb(pa_reserve_monitor_wrapper *w, void* busy, struct userdata *u) {
-    pa_bool_t b;
-
     pa_assert(w);
     pa_assert(u);
 
-    b = PA_PTR_TO_UINT(busy) && !u->reserve;
+    if (PA_PTR_TO_UINT(busy) && !u->reserve) {
+        pa_log_debug("Suspending source %s, because another application is blocking the access to the device.", u->source->name);
+        pa_source_suspend(u->source, true, PA_SUSPEND_APPLICATION);
+    } else {
+        pa_log_debug("Resuming source %s, because other applications aren't blocking access to the device any more.", u->source->name);
+        pa_source_suspend(u->source, false, PA_SUSPEND_APPLICATION);
+    }
 
-    pa_source_suspend(u->source, b, PA_SUSPEND_APPLICATION);
     return PA_HOOK_OK;
 }
 

src/modules/bluetooth/module-bluetooth-device.c

@@ -1422,12 +1422,16 @@ static DBusHandlerResult filter_cb(DBusConnection *bus, DBusMessage *m, void *us
 
     if (acquire)
         if (bt_transport_acquire(u, FALSE) >= 0) {
-            if (u->source)
+            if (u->source) {
+                pa_log_debug("Resuming source %s, because the bluetooth audio state changed to 'playing'.", u->source->name);
                 pa_source_suspend(u->source, FALSE, PA_SUSPEND_IDLE|PA_SUSPEND_USER);
+            }
 
-            if (u->sink)
+            if (u->sink) {
+                pa_log_debug("Resuming sink %s, because the bluetooth audio state changed to 'playing'.", u->sink->name);
                 pa_sink_suspend(u->sink, FALSE, PA_SUSPEND_IDLE|PA_SUSPEND_USER);
             }
+        }
 
     if (release && bt_transport_is_acquired(u)) {
         /* FIXME: this release is racy, since the audio stream might have
@@ -1436,12 +1440,16 @@ static DBusHandlerResult filter_cb(DBusConnection *bus, DBusMessage *m, void *us
            in that case we would just mark the transport as released */
 
         /* Remote side closed the stream so we consider it PA_SUSPEND_USER */
-        if (u->source)
+        if (u->source) {
+            pa_log_debug("Suspending source %s, because the remote end closed the stream.", u->source->name);
             pa_source_suspend(u->source, TRUE, PA_SUSPEND_USER);
+        }
 
-        if (u->sink)
+        if (u->sink) {
+            pa_log_debug("Suspending sink %s, because the remote end closed the stream.", u->sink->name);
             pa_sink_suspend(u->sink, TRUE, PA_SUSPEND_USER);
         }
+    }
 
 fail:
     dbus_error_free(&err);

src/modules/dbus/iface-device.c

@@ -923,20 +923,31 @@ static void handle_get_all(DBusConnection *conn, DBusMessage *msg, void *userdat
 static void handle_suspend(DBusConnection *conn, DBusMessage *msg, void *userdata) {
     pa_dbusiface_device *d = userdata;
     dbus_bool_t suspend = FALSE;
+    pa_client *client;
 
     pa_assert(conn);
     pa_assert(msg);
     pa_assert(d);
 
     pa_assert_se(dbus_message_get_args(msg, NULL, DBUS_TYPE_BOOLEAN, &suspend, DBUS_TYPE_INVALID));
+    pa_assert_se(client = pa_dbus_protocol_get_client(d->dbus_protocol, conn));
 
-    if ((d->type == PA_DEVICE_TYPE_SINK) && (pa_sink_suspend(d->sink, suspend, PA_SUSPEND_USER) < 0)) {
+    if (d->type == PA_DEVICE_TYPE_SINK) {
+        pa_log_debug("%s sink %s requested by client %" PRIu32 ".", suspend ? "Suspending" : "Resuming", d->sink->name, client->index);
+
+        if (pa_sink_suspend(d->sink, suspend, PA_SUSPEND_USER) < 0) {
             pa_dbus_send_error(conn, msg, DBUS_ERROR_FAILED, "Internal error in PulseAudio: pa_sink_suspend() failed.");
             return;
-    } else if ((d->type == PA_DEVICE_TYPE_SOURCE) && (pa_source_suspend(d->source, suspend, PA_SUSPEND_USER) < 0)) {
+        }
+
+    } else {
+        pa_log_debug("%s source %s requested by client %" PRIu32 ".", suspend ? "Suspending" : "Resuming", d->source->name, client->index);
+
+        if (pa_source_suspend(d->source, suspend, PA_SUSPEND_USER) < 0) {
             pa_dbus_send_error(conn, msg, DBUS_ERROR_FAILED, "Internal error in PulseAudio: pa_source_suspend() failed.");
             return;
         }
+    }
 
     pa_dbus_send_empty_reply(conn, msg);
 }

src/modules/module-suspend-on-idle.c

@@ -128,15 +128,13 @@ static void resume(struct device_info *d) {
     d->userdata->core->mainloop->time_restart(d->time_event, NULL);
 
     if (d->sink) {
+        pa_log_debug("Sink %s becomes busy, resuming.", d->sink->name);
         pa_sink_suspend(d->sink, FALSE, PA_SUSPEND_IDLE);
-
-        pa_log_debug("Sink %s becomes busy.", d->sink->name);
     }
 
     if (d->source) {
+        pa_log_debug("Source %s becomes busy, resuming.", d->source->name);
         pa_source_suspend(d->source, FALSE, PA_SUSPEND_IDLE);
-
-        pa_log_debug("Source %s becomes busy.", d->source->name);
     }
 }
 

src/modules/module-udev-detect.c

@@ -350,10 +350,12 @@ static void verify_access(struct userdata *u, struct device *d) {
         /* If we are already loaded update suspend status with
          * accessible boolean */
 
-        if ((card = pa_namereg_get(u->core, d->card_name, PA_NAMEREG_CARD)))
+        if ((card = pa_namereg_get(u->core, d->card_name, PA_NAMEREG_CARD))) {
+            pa_log_debug("%s all sinks and sources of card %s.", accessible ? "Resuming" : "Suspending", d->card_name);
             pa_card_suspend(card, !accessible, PA_SUSPEND_SESSION);
         }
     }
+}
 
 static void card_changed(struct userdata *u, struct udev_device *dev) {
     struct device *d;

src/modules/module-virtual-source.c

@@ -126,6 +126,7 @@ static int sink_set_state_cb(pa_sink *s, pa_sink_state_t state) {
 
     if (state == PA_SINK_RUNNING) {
         /* need to wake-up source if it was suspended */
+        pa_log_debug("Resuming source %s, because its uplink sink became active.", u->source->name);
         pa_source_suspend(u->source, FALSE, PA_SUSPEND_ALL);
 
         /* FIXME: if there's no client connected, the source will suspend

src/pulsecore/cli-command.c

@@ -1423,6 +1423,8 @@ static int pa_cli_command_suspend_sink(pa_core *c, pa_tokenizer *t, pa_strbuf *b
         return -1;
     }
 
+    pa_log_debug("%s of sink %s requested via CLI.", suspend ? "Suspending" : "Resuming", sink->name);
+
     if ((r = pa_sink_suspend(sink, suspend, PA_SUSPEND_USER)) < 0)
         pa_strbuf_printf(buf, "Failed to resume/suspend sink: %s\n", pa_strerror(r));
 
@@ -1459,6 +1461,8 @@ static int pa_cli_command_suspend_source(pa_core *c, pa_tokenizer *t, pa_strbuf
         return -1;
     }
 
+    pa_log_debug("%s of source %s requested via CLI.", suspend ? "Suspending" : "Resuming", source->name);
+
     if ((r = pa_source_suspend(source, suspend, PA_SUSPEND_USER)) < 0)
         pa_strbuf_printf(buf, "Failed to resume/suspend source: %s\n", pa_strerror(r));
 
@@ -1484,6 +1488,8 @@ static int pa_cli_command_suspend(pa_core *c, pa_tokenizer *t, pa_strbuf *buf, p
         return -1;
     }
 
+    pa_log_debug("%s of all sinks and sources requested via CLI.", suspend ? "Suspending" : "Resuming");
+
     if ((r = pa_sink_suspend_all(c, suspend, PA_SUSPEND_USER)) < 0)
         pa_strbuf_printf(buf, "Failed to resume/suspend all sinks: %s\n", pa_strerror(r));
 

src/pulsecore/protocol-esound.c

@@ -949,6 +949,9 @@ static int esd_proto_standby_or_resume(connection *c, esd_proto_t request, const
     connection_write_prepare(c, sizeof(int32_t) * 2);
     connection_write(c, &ok, sizeof(int32_t));
 
+    pa_log_debug("%s of all sinks and sources requested by client %" PRIu32 ".",
+                 request == ESD_PROTO_STANDBY ? "Suspending" : "Resuming", c->client->index);
+
     if (request == ESD_PROTO_STANDBY) {
         ok = pa_sink_suspend_all(c->protocol->core, true, PA_SUSPEND_USER) >= 0;
         ok &= pa_source_suspend_all(c->protocol->core, true, PA_SUSPEND_USER) >= 0;

src/pulsecore/protocol-native.c

@@ -4552,6 +4552,9 @@ static void command_suspend(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa
 
             CHECK_VALIDITY(c->pstream, sink, tag, PA_ERR_NOENTITY);
 
+            pa_log_debug("%s of sink %s requested by client %" PRIu32 ".",
+                         b ? "Suspending" : "Resuming", sink->name, c->client->index);
+
             if (pa_sink_suspend(sink, b, PA_SUSPEND_USER) < 0) {
                 pa_pstream_send_error(c->pstream, tag, PA_ERR_INVALID);
                 return;
@@ -4580,6 +4583,9 @@ static void command_suspend(pa_pdispatch *pd, uint32_t command, uint32_t tag, pa
 
             CHECK_VALIDITY(c->pstream, source, tag, PA_ERR_NOENTITY);
 
+            pa_log_debug("%s of source %s requested by client %" PRIu32 ".",
+                         b ? "Suspending" : "Resuming", source->name, c->client->index);
+
             if (pa_source_suspend(source, b, PA_SUSPEND_USER) < 0) {
                 pa_pstream_send_error(c->pstream, tag, PA_ERR_INVALID);
                 return;

src/pulsecore/sink.c

@@ -1395,6 +1395,7 @@ pa_bool_t pa_sink_update_rate(pa_sink *s, uint32_t rate, pa_bool_t passthrough)
         if (!passthrough && pa_sink_used_by(s) > 0)
             return FALSE;
 
+        pa_log_debug("Suspending sink %s due to changing the sample rate.", s->name);
         pa_sink_suspend(s, TRUE, PA_SUSPEND_IDLE); /* needed before rate update, will be resumed automatically */
 
         if (s->update_rate(s, desired_rate) == TRUE) {
@@ -1531,8 +1532,10 @@ void pa_sink_enter_passthrough(pa_sink *s) {
     pa_cvolume volume;
 
     /* disable the monitor in passthrough mode */
-    if (s->monitor_source)
+    if (s->monitor_source) {
+        pa_log_debug("Suspending monitor source %s, because the sink is entering the passthrough mode.", s->monitor_source->name);
         pa_source_suspend(s->monitor_source, TRUE, PA_SUSPEND_PASSTHROUGH);
+    }
 
     /* set the volume to NORM */
     s->saved_volume = *pa_sink_get_volume(s, TRUE);
@@ -1545,8 +1548,10 @@ void pa_sink_enter_passthrough(pa_sink *s) {
 /* Called from main context */
 void pa_sink_leave_passthrough(pa_sink *s) {
     /* Unsuspend monitor */
-    if (s->monitor_source)
+    if (s->monitor_source) {
+        pa_log_debug("Resuming monitor source %s, because the sink is leaving the passthrough mode.", s->monitor_source->name);
         pa_source_suspend(s->monitor_source, FALSE, PA_SUSPEND_PASSTHROUGH);
+    }
 
     /* Restore sink volume to what it was before we entered passthrough mode */
     pa_sink_set_volume(s, &s->saved_volume, TRUE, s->saved_save_volume);

src/pulsecore/source.c

@@ -1006,6 +1006,7 @@ pa_bool_t pa_source_update_rate(pa_source *s, uint32_t rate, pa_bool_t passthrou
         if (!passthrough && pa_source_used_by(s) > 0)
             return FALSE;
 
+        pa_log_debug("Suspending source %s due to changing the sample rate.", s->name);
         pa_source_suspend(s, TRUE, PA_SUSPEND_IDLE); /* needed before rate update, will be resumed automatically */
 
         if (s->update_rate(s, desired_rate) == TRUE) {