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

[Tanu Kaskinen]

On Thu, 2018-07-26 at 13:57 -0700, João Paulo Rechi Vita wrote:
> On Fri, Jun 29, 2018 at 5:02 AM, Tanu Kaskinen <tanuk at iki.fi> wrote:
> > On Wed, 2018-06-27 at 15:01 -0700, João Paulo Rechi Vita wrote:
> > > ---
> > >  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);
> > 
> > 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).
> > 
> 
> (sorry it took me so long to reply to this)

(slow replies continue)

> 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.

> 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