card: Log availability status when choosing initial profile

Submitted by João Paulo Rechi Vita on June 27, 2018, 10:01 p.m.

Details

Message ID 20180627220154.3990-1-jprvita@endlessm.com
State New
Series "card: Log availability status when choosing initial profile"
Headers show

Commit Message

João Paulo Rechi Vita June 27, 2018, 10:01 p.m.
---
 src/pulsecore/card.c | 5 +++++
 1 file changed, 5 insertions(+)

Patch hide | download patch | download mbox

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;
 

Comments

João Paulo Rechi Vita June 28, 2018, 7:16 p.m.
On Wed, Jun 27, 2018 at 3:01 PM, João Paulo Rechi Vita
<jprvita@gmail.com> 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);
>      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 June 29, 2018, 12:02 p.m.
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).
João Paulo Rechi Vita July 26, 2018, 8:57 p.m.
On Fri, Jun 29, 2018 at 5:02 AM, Tanu Kaskinen <tanuk@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)

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 Aug. 13, 2018, 11:57 a.m.
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@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);
João Paulo Rechi Vita Aug. 20, 2018, 9:05 p.m.
On Mon, Aug 13, 2018 at 4:57 AM, Tanu Kaskinen <tanuk@iki.fi> wrote:
> 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@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.
>

Ok.

>> 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);
>

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