Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Mon, 16 May 2022 09:49:04 +0200
Message-ID: <s5h35h9c3yn.wl-tiwai@suse.de>
From:   Takashi Iwai <tiwai@suse.de>
To:     Siddh Raman Pant <siddhpant.gh@gmail.com>
Cc:     Mark Brown <broonie@kernel.org>, Jaroslav Kysela <perex@perex.cz>,
        Takashi Iwai <tiwai@suse.com>,
        Shuah Khan <skhan@linuxfoundation.org>,
        alsa-devel@alsa-project.org, linux-kselftest@vger.kernel.org,
        linux-kernel@vger.kernel.org
Subject: Re: [PATCH] selftests: alsa: Better error messages
In-Reply-To: <8598037d-0e24-9bc1-3f2c-a2751ec8e871@gmail.com>
References: <8598037d-0e24-9bc1-3f2c-a2751ec8e871@gmail.com>
User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI/1.14.6 (Maruoka)
 FLIM/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL/10.8 Emacs/25.3
 (x86_64-suse-linux-gnu) MULE/6.0 (HANACHIRUSATO)
MIME-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka")
Content-Type: text/plain; charset=US-ASCII
Precedence: bulk

On Fri, 13 May 2022 15:40:57 +0200,
Siddh Raman Pant wrote:
> 
> This allows for potentially better machine-parsing due to an
> expected / fixed format. Also because of eyecandy reasons.
> 
> Whenever possible, errors will start with the name of the
> offending card/control, separated by the error with colons.
> 
> Whenever there is a description of an error given, the generated
> error string from snd_strerror will be (mostly) enclosed in
> parentheses at the end.
> 
> Clarity of error messages have been (hopefully) improved.
> 
> Signed-off-by: Siddh Raman Pant <siddhpant.gh@gmail.com>

Thanks for the patch.

But, honestly speaking, I'm not sure whether it worth.
Although it's possibly a bit more consistent over all texts, I
don't see significant improvement by this change.

But I'm fine to apply it, so keep this pending and would like to
hear from others.


thanks,

Takashi

> ---
>  tools/testing/selftests/alsa/mixer-test.c | 94 +++++++++++------------
>  1 file changed, 47 insertions(+), 47 deletions(-)
> 
> diff --git a/tools/testing/selftests/alsa/mixer-test.c b/tools/testing/selftests/alsa/mixer-test.c
> index a38b89c28..4719b12a5 100644
> --- a/tools/testing/selftests/alsa/mixer-test.c
> +++ b/tools/testing/selftests/alsa/mixer-test.c
> @@ -114,7 +114,7 @@ static void find_controls(void)
>  
>  	err = snd_config_load_string(&config, alsa_config, strlen(alsa_config));
>  	if (err < 0) {
> -		ksft_print_msg("Unable to parse custom alsa-lib configuration: %s\n",
> +		ksft_print_msg("Unable to parse custom alsa-lib configuration (%s)\n",
>  			       snd_strerror(err));
>  		ksft_exit_fail();
>  	}
> @@ -128,7 +128,7 @@ static void find_controls(void)
>  
>  		err = snd_ctl_open_lconf(&card_data->handle, name, 0, config);
>  		if (err < 0) {
> -			ksft_print_msg("Failed to get hctl for card %d: %s\n",
> +			ksft_print_msg("Card %d: Failed to get hctl (%s)\n",
>  				       card, snd_strerror(err));
>  			goto next_card;
>  		}
> @@ -177,9 +177,8 @@ static void find_controls(void)
>  			err = snd_ctl_elem_info(card_data->handle,
>  						ctl_data->info);
>  			if (err < 0) {
> -				ksft_print_msg("%s getting info for %d\n",
> -					       snd_strerror(err),
> -					       ctl_data->name);
> +				ksft_print_msg("%s : %s while getting info\n",
> +					       ctl_data->name, snd_strerror(err));
>  			}
>  
>  			snd_ctl_elem_value_set_id(ctl_data->def_val,
> @@ -192,20 +191,20 @@ static void find_controls(void)
>  		/* Set up for events */
>  		err = snd_ctl_subscribe_events(card_data->handle, true);
>  		if (err < 0) {
> -			ksft_exit_fail_msg("snd_ctl_subscribe_events() failed for card %d: %d\n",
> +			ksft_exit_fail_msg("Card %d : snd_ctl_subscribe_events() failed (%d)\n",
>  					   card, err);
>  		}
>  
>  		err = snd_ctl_poll_descriptors_count(card_data->handle);
>  		if (err != 1) {
> -			ksft_exit_fail_msg("Unexpected descriptor count %d for card %d\n",
> -					   err, card);
> +			ksft_exit_fail_msg("Card %d : Unexpected descriptor count %d\n",
> +					   card, err);
>  		}
>  
>  		err = snd_ctl_poll_descriptors(card_data->handle,
>  					       &card_data->pollfd, 1);
>  		if (err != 1) {
> -			ksft_exit_fail_msg("snd_ctl_poll_descriptors() failed for %d\n",
> +			ksft_exit_fail_msg("Card %d : snd_ctl_poll_descriptors() failed (%d)\n",
>  				       card, err);
>  		}
>  
> @@ -236,8 +235,8 @@ static int wait_for_event(struct ctl_data *ctl, int timeout)
>  	do {
>  		err = poll(&(ctl->card->pollfd), 1, timeout);
>  		if (err < 0) {
> -			ksft_print_msg("poll() failed for %s: %s (%d)\n",
> -				       ctl->name, strerror(errno), errno);
> +			ksft_print_msg("%s : poll() failed (%d - %s)\n",
> +				       ctl->name, errno, strerror(errno));
>  			return -1;
>  		}
>  		/* Timeout */
> @@ -248,12 +247,12 @@ static int wait_for_event(struct ctl_data *ctl, int timeout)
>  						       &(ctl->card->pollfd),
>  						       1, &revents);
>  		if (err < 0) {
> -			ksft_print_msg("snd_ctl_poll_descriptors_revents() failed for %s: %d\n",
> +			ksft_print_msg("%s : snd_ctl_poll_descriptors_revents() failed (%d)\n",
>  				       ctl->name, err);
>  			return err;
>  		}
>  		if (revents & POLLERR) {
> -			ksft_print_msg("snd_ctl_poll_descriptors_revents() reported POLLERR for %s\n",
> +			ksft_print_msg("%s : snd_ctl_poll_descriptors_revents() reported POLLERR\n",
>  				       ctl->name);
>  			return -1;
>  		}
> @@ -265,7 +264,7 @@ static int wait_for_event(struct ctl_data *ctl, int timeout)
>  
>  		err = snd_ctl_read(ctl->card->handle, event);
>  		if (err < 0) {
> -			ksft_print_msg("snd_ctl_read() failed for %s: %d\n",
> +			ksft_print_msg("%s : snd_ctl_read() failed (%d)\n",
>  			       ctl->name, err);
>  			return err;
>  		}
> @@ -283,7 +282,7 @@ static int wait_for_event(struct ctl_data *ctl, int timeout)
>  		}
>  
>  		if ((mask & SND_CTL_EVENT_MASK_REMOVE) == SND_CTL_EVENT_MASK_REMOVE) {
> -			ksft_print_msg("Removal event for %s\n",
> +			ksft_print_msg("%s : Removal event\n",
>  				       ctl->name);
>  			return -1;
>  		}
> @@ -301,7 +300,7 @@ static bool ctl_value_index_valid(struct ctl_data *ctl,
>  
>  	switch (snd_ctl_elem_info_get_type(ctl->info)) {
>  	case SND_CTL_ELEM_TYPE_NONE:
> -		ksft_print_msg("%s.%d Invalid control type NONE\n",
> +		ksft_print_msg("%s.%d : Invalid control type NONE\n",
>  			       ctl->name, index);
>  		return false;
>  
> @@ -312,7 +311,7 @@ static bool ctl_value_index_valid(struct ctl_data *ctl,
>  		case 1:
>  			break;
>  		default:
> -			ksft_print_msg("%s.%d Invalid boolean value %ld\n",
> +			ksft_print_msg("%s.%d : Invalid boolean value %ld\n",
>  				       ctl->name, index, int_val);
>  			return false;
>  		}
> @@ -322,14 +321,14 @@ static bool ctl_value_index_valid(struct ctl_data *ctl,
>  		int_val = snd_ctl_elem_value_get_integer(val, index);
>  
>  		if (int_val < snd_ctl_elem_info_get_min(ctl->info)) {
> -			ksft_print_msg("%s.%d value %ld less than minimum %ld\n",
> +			ksft_print_msg("%s.%d : Value %ld is less than the minimum (%ld)\n",
>  				       ctl->name, index, int_val,
>  				       snd_ctl_elem_info_get_min(ctl->info));
>  			return false;
>  		}
>  
>  		if (int_val > snd_ctl_elem_info_get_max(ctl->info)) {
> -			ksft_print_msg("%s.%d value %ld more than maximum %ld\n",
> +			ksft_print_msg("%s.%d : Value %ld is more than the maximum (%ld)\n",
>  				       ctl->name, index, int_val,
>  				       snd_ctl_elem_info_get_max(ctl->info));
>  			return false;
> @@ -339,7 +338,7 @@ static bool ctl_value_index_valid(struct ctl_data *ctl,
>  		if (snd_ctl_elem_info_get_step(ctl->info) &&
>  		    (int_val - snd_ctl_elem_info_get_min(ctl->info) %
>  		     snd_ctl_elem_info_get_step(ctl->info))) {
> -			ksft_print_msg("%s.%d value %ld invalid for step %ld minimum %ld\n",
> +			ksft_print_msg("%s.%d : Value %ld is invalid for step %ld, minimum %ld\n",
>  				       ctl->name, index, int_val,
>  				       snd_ctl_elem_info_get_step(ctl->info),
>  				       snd_ctl_elem_info_get_min(ctl->info));
> @@ -351,14 +350,14 @@ static bool ctl_value_index_valid(struct ctl_data *ctl,
>  		int64_val = snd_ctl_elem_value_get_integer64(val, index);
>  
>  		if (int64_val < snd_ctl_elem_info_get_min64(ctl->info)) {
> -			ksft_print_msg("%s.%d value %lld less than minimum %lld\n",
> +			ksft_print_msg("%s.%d : Value %lld is less than the minimum (%lld)\n",
>  				       ctl->name, index, int64_val,
>  				       snd_ctl_elem_info_get_min64(ctl->info));
>  			return false;
>  		}
>  
>  		if (int64_val > snd_ctl_elem_info_get_max64(ctl->info)) {
> -			ksft_print_msg("%s.%d value %lld more than maximum %lld\n",
> +			ksft_print_msg("%s.%d : Value %lld is more than the maximum (%lld)\n",
>  				       ctl->name, index, int64_val,
>  				       snd_ctl_elem_info_get_max(ctl->info));
>  			return false;
> @@ -368,7 +367,7 @@ static bool ctl_value_index_valid(struct ctl_data *ctl,
>  		if (snd_ctl_elem_info_get_step64(ctl->info) &&
>  		    (int64_val - snd_ctl_elem_info_get_min64(ctl->info)) %
>  		    snd_ctl_elem_info_get_step64(ctl->info)) {
> -			ksft_print_msg("%s.%d value %lld invalid for step %lld minimum %lld\n",
> +			ksft_print_msg("%s.%d : Value %lld is invalid for step %lld, minimum %lld\n",
>  				       ctl->name, index, int64_val,
>  				       snd_ctl_elem_info_get_step64(ctl->info),
>  				       snd_ctl_elem_info_get_min64(ctl->info));
> @@ -380,13 +379,13 @@ static bool ctl_value_index_valid(struct ctl_data *ctl,
>  		int_val = snd_ctl_elem_value_get_enumerated(val, index);
>  
>  		if (int_val < 0) {
> -			ksft_print_msg("%s.%d negative value %ld for enumeration\n",
> +			ksft_print_msg("%s.%d : Negative value %ld for enumeration\n",
>  				       ctl->name, index, int_val);
>  			return false;
>  		}
>  
>  		if (int_val >= snd_ctl_elem_info_get_items(ctl->info)) {
> -			ksft_print_msg("%s.%d value %ld more than item count %ld\n",
> +			ksft_print_msg("%s.%d : Value %ld is more than item count (%ld)\n",
>  				       ctl->name, index, int_val,
>  				       snd_ctl_elem_info_get_items(ctl->info));
>  			return false;
> @@ -427,7 +426,7 @@ static void test_ctl_get_value(struct ctl_data *ctl)
>  
>  	/* If the control is turned off let's be polite */
>  	if (snd_ctl_elem_info_is_inactive(ctl->info)) {
> -		ksft_print_msg("%s is inactive\n", ctl->name);
> +		ksft_print_msg("%s : Inactive\n", ctl->name);
>  		ksft_test_result_skip("get_value.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
> @@ -435,7 +434,7 @@ static void test_ctl_get_value(struct ctl_data *ctl)
>  
>  	/* Can't test reading on an unreadable control */
>  	if (!snd_ctl_elem_info_is_readable(ctl->info)) {
> -		ksft_print_msg("%s is not readable\n", ctl->name);
> +		ksft_print_msg("%s : Not readable\n", ctl->name);
>  		ksft_test_result_skip("get_value.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
> @@ -443,7 +442,7 @@ static void test_ctl_get_value(struct ctl_data *ctl)
>  
>  	err = snd_ctl_elem_read(ctl->card->handle, ctl->def_val);
>  	if (err < 0) {
> -		ksft_print_msg("snd_ctl_elem_read() failed: %s\n",
> +		ksft_print_msg("snd_ctl_elem_read() failed (%s)\n",
>  			       snd_strerror(err));
>  		goto out;
>  	}
> @@ -474,7 +473,7 @@ static void test_ctl_name(struct ctl_data *ctl)
>  	/* Only boolean controls should end in Switch */
>  	if (strend(ctl->name, " Switch")) {
>  		if (snd_ctl_elem_info_get_type(ctl->info) != SND_CTL_ELEM_TYPE_BOOLEAN) {
> -			ksft_print_msg("%d.%d %s ends in Switch but is not boolean\n",
> +			ksft_print_msg("%d.%d %s : Not a boolean, but name ends in Switch\n",
>  				       ctl->card->card, ctl->elem, ctl->name);
>  			name_ok = false;
>  		}
> @@ -484,7 +483,7 @@ static void test_ctl_name(struct ctl_data *ctl)
>  	if (snd_ctl_elem_info_get_type(ctl->info) == SND_CTL_ELEM_TYPE_BOOLEAN &&
>  	    snd_ctl_elem_info_is_writable(ctl->info)) {
>  		if (!strend(ctl->name, " Switch")) {
> -			ksft_print_msg("%d.%d %s is a writeable boolean but not a Switch\n",
> +			ksft_print_msg("%d.%d %s : Not a Switch despite being a writeable boolean\n",
>  				       ctl->card->card, ctl->elem, ctl->name);
>  			name_ok = false;
>  		}
> @@ -542,11 +541,12 @@ static bool show_mismatch(struct ctl_data *ctl, int index,
>  		/*
>  		 * NOTE: The volatile attribute means that the hardware
>  		 * can voluntarily change the state of control element
> -		 * independent of any operation by software.  
> +		 * independent of any operation by software.
>  		 */
>  		bool is_volatile = snd_ctl_elem_info_is_volatile(ctl->info);
> -		ksft_print_msg("%s.%d expected %lld but read %lld, is_volatile %d\n",
> -			       ctl->name, index, expected_int, read_int, is_volatile);
> +		ksft_print_msg("%s.%d : Expected %lld, but read %lld (%s)\n",
> +			       ctl->name, index, expected_int, read_int,
> +			       (is_volatile ? "Volatile" : "Non-volatile"));
>  		return !is_volatile;
>  	} else {
>  		return false;
> @@ -590,7 +590,7 @@ static int write_and_verify(struct ctl_data *ctl,
>  
>  		err = snd_ctl_elem_read(ctl->card->handle, initial_val);
>  		if (err < 0) {
> -			ksft_print_msg("snd_ctl_elem_read() failed: %s\n",
> +			ksft_print_msg("snd_ctl_elem_read() failed (%s)\n",
>  				       snd_strerror(err));
>  			return err;
>  		}
> @@ -602,7 +602,7 @@ static int write_and_verify(struct ctl_data *ctl,
>  	 */
>  	err = snd_ctl_elem_write(ctl->card->handle, w_val);
>  	if (err < 0 && !error_expected) {
> -		ksft_print_msg("snd_ctl_elem_write() failed: %s\n",
> +		ksft_print_msg("snd_ctl_elem_write() failed (%s)\n",
>  			       snd_strerror(err));
>  		return err;
>  	}
> @@ -615,7 +615,7 @@ static int write_and_verify(struct ctl_data *ctl,
>  
>  	err = snd_ctl_elem_read(ctl->card->handle, read_val);
>  	if (err < 0) {
> -		ksft_print_msg("snd_ctl_elem_read() failed: %s\n",
> +		ksft_print_msg("snd_ctl_elem_read() failed (%s)\n",
>  			       snd_strerror(err));
>  		return err;
>  	}
> @@ -631,13 +631,13 @@ static int write_and_verify(struct ctl_data *ctl,
>  		err = wait_for_event(ctl, 0);
>  		if (snd_ctl_elem_value_compare(initial_val, read_val)) {
>  			if (err < 1) {
> -				ksft_print_msg("No event generated for %s\n",
> +				ksft_print_msg("%s : No event generated\n",
>  					       ctl->name);
>  				ctl->event_missing++;
>  			}
>  		} else {
>  			if (err != 0) {
> -				ksft_print_msg("Spurious event generated for %s\n",
> +				ksft_print_msg("%s : Spurious event generated\n",
>  					       ctl->name);
>  				ctl->event_spurious++;
>  			}
> @@ -658,7 +658,7 @@ static int write_and_verify(struct ctl_data *ctl,
>  			mismatch_shown = true;
>  
>  	if (!mismatch_shown)
> -		ksft_print_msg("%s read and written values differ\n",
> +		ksft_print_msg("%s : Read and written values differ\n",
>  			       ctl->name);
>  
>  	return -1;
> @@ -674,14 +674,14 @@ static void test_ctl_write_default(struct ctl_data *ctl)
>  
>  	/* If the control is turned off let's be polite */
>  	if (snd_ctl_elem_info_is_inactive(ctl->info)) {
> -		ksft_print_msg("%s is inactive\n", ctl->name);
> +		ksft_print_msg("%s : Inactive\n", ctl->name);
>  		ksft_test_result_skip("write_default.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
>  	}
>  
>  	if (!snd_ctl_elem_info_is_writable(ctl->info)) {
> -		ksft_print_msg("%s is not writeable\n", ctl->name);
> +		ksft_print_msg("%s : Not writeable\n", ctl->name);
>  		ksft_test_result_skip("write_default.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
> @@ -689,7 +689,7 @@ static void test_ctl_write_default(struct ctl_data *ctl)
>  
>  	/* No idea what the default was for unreadable controls */
>  	if (!snd_ctl_elem_info_is_readable(ctl->info)) {
> -		ksft_print_msg("%s couldn't read default\n", ctl->name);
> +		ksft_print_msg("%s : Couldn't read default\n", ctl->name);
>  		ksft_test_result_skip("write_default.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
> @@ -808,14 +808,14 @@ static void test_ctl_write_valid(struct ctl_data *ctl)
>  
>  	/* If the control is turned off let's be polite */
>  	if (snd_ctl_elem_info_is_inactive(ctl->info)) {
> -		ksft_print_msg("%s is inactive\n", ctl->name);
> +		ksft_print_msg("%s : Inactive\n", ctl->name);
>  		ksft_test_result_skip("write_valid.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
>  	}
>  
>  	if (!snd_ctl_elem_info_is_writable(ctl->info)) {
> -		ksft_print_msg("%s is not writeable\n", ctl->name);
> +		ksft_print_msg("%s : Not writeable\n", ctl->name);
>  		ksft_test_result_skip("write_valid.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
> @@ -868,7 +868,7 @@ static bool test_ctl_write_invalid_value(struct ctl_data *ctl,
>  	/* ...but some devices will clamp to an in range value */
>  	err = snd_ctl_elem_read(ctl->card->handle, val);
>  	if (err < 0) {
> -		ksft_print_msg("%s failed to read: %s\n",
> +		ksft_print_msg("%s : Failed to read (%s)\n",
>  			       ctl->name, snd_strerror(err));
>  		return true;
>  	}
> @@ -1026,14 +1026,14 @@ static void test_ctl_write_invalid(struct ctl_data *ctl)
>  
>  	/* If the control is turned off let's be polite */
>  	if (snd_ctl_elem_info_is_inactive(ctl->info)) {
> -		ksft_print_msg("%s is inactive\n", ctl->name);
> +		ksft_print_msg("%s : Inactive\n", ctl->name);
>  		ksft_test_result_skip("write_invalid.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
>  	}
>  
>  	if (!snd_ctl_elem_info_is_writable(ctl->info)) {
> -		ksft_print_msg("%s is not writeable\n", ctl->name);
> +		ksft_print_msg("%s : Not writeable\n", ctl->name);
>  		ksft_test_result_skip("write_invalid.%d.%d\n",
>  				      ctl->card->card, ctl->elem);
>  		return;
> -- 
> 2.35.1
>