[pulseaudio-discuss] [PATCH] card: Log availability status when choosing initial profile

Discussion:

João Paulo Rechi Vita

2018-06-27 22:01:54 UTC

---
src/pulsecore/card.c | 5 +++++
1 file changed, 5 insertions(+)

diff --git a/src/pulsecore/card.c b/src/pulsecore/card.c
index 0112cffb1..4ead3a606 100644
--- a/src/pulsecore/card.c
+++ b/src/pulsecore/card.c
@@ -204,7 +204,10 @@ void pa_card_choose_initial_profile(pa_card *card) {
* or if all profiles are unavailable, pick the profile with the highest
* priority regardless of its availability. */

+ pa_log_debug("Looking for an initial profile for card %s", card->name);
PA_HASHMAP_FOREACH(profile, card->profiles, state) {
+ pa_log_debug("profile %s availability %s", profile->name, profile->available == PA_AVAILABLE_YES ? "yes" :
+ profile->available == PA_AVAILABLE_NO ? "no" : "unknown");
if (profile->available == PA_AVAILABLE_NO)
continue;

@@ -213,6 +216,7 @@ void pa_card_choose_initial_profile(pa_card *card) {
}

if (!best) {
+ pa_log_info("No profile with availability status 'yes' or 'unknown' found for card %s", card->name);
PA_HASHMAP_FOREACH(profile, card->profiles, state) {
if (!best || profile->priority > best->priority)
best = profile;
@@ -220,6 +224,7 @@ void pa_card_choose_initial_profile(pa_card *card) {
}
pa_assert(best);

+ pa_log_info("Initial profile %s chosen for card %s", best->name, card->name);
card->active_profile = best;
card->save_profile = false;

--
2.18.0

João Paulo Rechi Vita

2018-06-28 19:16:03 UTC

Permalink

On Wed, Jun 27, 2018 at 3:01 PM, João Paulo Rechi Vita

Post by JoÃ£o Paulo Rechi Vita
---
src/pulsecore/card.c | 5 +++++
1 file changed, 5 insertions(+)
diff --git a/src/pulsecore/card.c b/src/pulsecore/card.c
index 0112cffb1..4ead3a606 100644
--- a/src/pulsecore/card.c
+++ b/src/pulsecore/card.c
@@ -204,7 +204,10 @@ void pa_card_choose_initial_profile(pa_card *card) {
* or if all profiles are unavailable, pick the profile with the highest
* priority regardless of its availability. */
+ pa_log_debug("Looking for an initial profile for card %s", card->name);
PA_HASHMAP_FOREACH(profile, card->profiles, state) {
+ profile->available == PA_AVAILABLE_NO ? "no" : "unknown");
if (profile->available == PA_AVAILABLE_NO)
continue;
@@ -213,6 +216,7 @@ void pa_card_choose_initial_profile(pa_card *card) {
}
if (!best) {
+ pa_log_info("No profile with availability status 'yes' or 'unknown' found for card %s", card->name);
PA_HASHMAP_FOREACH(profile, card->profiles, state) {
if (!best || profile->priority > best->priority)
best = profile;
@@ -220,6 +224,7 @@ void pa_card_choose_initial_profile(pa_card *card) {
}
pa_assert(best);
+ pa_log_info("Initial profile %s chosen for card %s", best->name, card->name);
card->active_profile = best;
card->save_profile = false;

Just to give the reasoning behind this patch (which I should probably
have added to the commit message, sorry): this was very helpful when
debugging Bluetooth headset profiles failing to connect depending on
the order they were getting connected, so I figured it would be useful
to have upstream for future problems.

--
João Paulo Rechi Vita
http://about.me/jprvita

Tanu Kaskinen

2018-06-29 12:02:58 UTC

Permalink

This message belongs to pa_card_put(), because at this point the
initial profile may still change, either in the CHOOSE_INITIAL_PROFILE
hook or by the card implementation (at least module-alsa-card supports
overriding the automatic policy). If you need to log a message at this
point, the wording needs to be different (I couldn't immediately come
up with a good example).

--
Tanu

https://liberapay.com/tanuk
https://www.patreon.com/tanuk

João Paulo Rechi Vita

2018-07-26 20:57:01 UTC

Permalink

Post by Tanu Kaskinen

(sorry it took me so long to reply to this)

Yes, I understand the initial profile may still change at this point,
but what I'm trying to log here is the whole logic to decide the
initial profile, starting from this point. Modules handling the
CHOOSE_INITIAL_PROFILE trigger should probably log a debug message
about it. The only two modules I've found that connect callbacks to
CHOOSE_INITIAL_PROFILE are module-card-restore and
module-bluetooth-policy, both of which log a message about it.

About the module-alsa-card override, I think you are referring to when
it is loaded with the "profile" modarg, we would also get a message
from pa_card_set_profile.

But I understand your point of trying to be clear that this initial
choice is subject to change before the card is active and available.
Maybe something like ("Profile %s chosen during card %s creation",
best->name, card->name) would achieve it?

--
João Paulo Rechi Vita
http://about.me/jprvita

Tanu Kaskinen

2018-08-13 11:57:26 UTC

Permalink

Post by JoÃ£o Paulo Rechi Vita

Post by Tanu Kaskinen

(sorry it took me so long to reply to this)

(slow replies continue)

Post by JoÃ£o Paulo Rechi Vita
Yes, I understand the initial profile may still change at this point,
but what I'm trying to log here is the whole logic to decide the
initial profile, starting from this point. Modules handling the
CHOOSE_INITIAL_PROFILE trigger should probably log a debug message
about it. The only two modules I've found that connect callbacks to
CHOOSE_INITIAL_PROFILE are module-card-restore and
module-bluetooth-policy, both of which log a message about it.
About the module-alsa-card override, I think you are referring to when
it is loaded with the "profile" modarg, we would also get a message
from pa_card_set_profile.

pa_card_set_profile() doesn't log anything before pa_card_put() has
been called. If you want detailed logs about the profile
initialization, I suppose we should change pa_card_set_profile() so
that it logs changes always.

Post by JoÃ£o Paulo Rechi Vita
But I understand your point of trying to be clear that this initial
choice is subject to change before the card is active and available.
Maybe something like ("Profile %s chosen during card %s creation",
best->name, card->name) would achieve it?

That's better, I'd accept that. Here's another suggestion:

pa_log_info("%s: active_profile: %s", card->name, card->active_profile->name);

That would be somewhat similar to the format that I nowadays prefer to
use for variable change messages (pa_card_set_profile() could be
updated to use this too):

pa_log_info("%s: variable: %s -> %s", object->name, old_value, new_value);

--
Tanu

https://www.patreon.com/tanuk
https://liberapay.com/tanuk

João Paulo Rechi Vita

2018-08-20 21:05:09 UTC

Permalink

Post by Tanu Kaskinen

Post by JoÃ£o Paulo Rechi Vita

Post by Tanu Kaskinen

(sorry it took me so long to reply to this)

(slow replies continue)

Ok.

Post by Tanu Kaskinen

pa_log_info("%s: active_profile: %s", card->name, card->active_profile->name);
That would be somewhat similar to the format that I nowadays prefer to
use for variable change messages (pa_card_set_profile() could be
pa_log_info("%s: variable: %s -> %s", object->name, old_value, new_value);

I'm all for consistency, so I went with your suggestions here.

Submitted an updated version through GitLab:
https://gitlab.freedesktop.org/pulseaudio/pulseaudio/merge_requests/3.

--
João Paulo Rechi Vita
http://about.me/jprvita