From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 8258CC433F5 for ; Mon, 16 May 2022 07:49:11 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S241255AbiEPHtK (ORCPT ); Mon, 16 May 2022 03:49:10 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:56986 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S241223AbiEPHtI (ORCPT ); Mon, 16 May 2022 03:49:08 -0400 Received: from smtp-out2.suse.de (smtp-out2.suse.de [195.135.220.29]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id D08B025E82; Mon, 16 May 2022 00:49:05 -0700 (PDT) Received: from relay2.suse.de (relay2.suse.de [149.44.160.134]) by smtp-out2.suse.de (Postfix) with ESMTP id 843DC1FB1D; Mon, 16 May 2022 07:49:04 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=suse.de; s=susede2_rsa; t=1652687344; h=from:from:reply-to:date:date:message-id:message-id:to:to:cc:cc: mime-version:mime-version:content-type:content-type: in-reply-to:in-reply-to:references:references; bh=FHfbjQvmgeHMVCppWrjk3qvoQCSGOOt7FMv3LUPp5v0=; b=MVKBLLVJCiC63Oqw+aIw04HPqFriHhogPGQN02LxTvKsLo+RV7rKYkNYR/cEQbBx7mgco+ Xed3hNrt+2eZlt4ZJLvNH7YboXFjSpGAg7bixKE4aJvbGr2/1VWVVJ6ipyzN9qu+clazWn +uAxYy/mESrfdJnF3ljv8y8NuSw6Yv8= DKIM-Signature: v=1; a=ed25519-sha256; c=relaxed/relaxed; d=suse.de; s=susede2_ed25519; t=1652687344; h=from:from:reply-to:date:date:message-id:message-id:to:to:cc:cc: mime-version:mime-version:content-type:content-type: in-reply-to:in-reply-to:references:references; bh=FHfbjQvmgeHMVCppWrjk3qvoQCSGOOt7FMv3LUPp5v0=; b=fZxyJvYSDpa3bvNa/nG5l+Zz8b+36hHsOOf+fNzeIzNiQgoNoK0M+YkFLf9CTJpGvl655y vglPOogyDqFjdQAw== Received: from alsa1.suse.de (alsa1.suse.de [10.160.4.42]) by relay2.suse.de (Postfix) with ESMTP id 746822C142; Mon, 16 May 2022 07:49:04 +0000 (UTC) Date: Mon, 16 May 2022 09:49:04 +0200 Message-ID: From: Takashi Iwai To: Siddh Raman Pant Cc: Mark Brown , Jaroslav Kysela , Takashi Iwai , Shuah Khan , 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 List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 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 >