From: Theo Buehler <tb@theobuehler.org>
Subject: Re: [patch] libressl: add more logs for asn1_time_compare_test
To: Kenjiro Nakayama <nakayamakenjiro@gmail.com>
Cc: tech@openbsd.org
Date: Sun, 21 Jul 2024 12:29:02 +0200

On Sun, Jul 21, 2024 at 07:10:01PM +0900, Kenjiro Nakayama wrote:
> When one of the asn1_time_compare_test fails, it is difficult to
> determine which test failed.
> 
> For example, currently it just outputs:
> 
> ```
> $ ./tests/asn1time 
>   ... (snip)...
> ASN1_TIME_compare tests...
> 140524144512Z vs. 150923032700Z: want -1, got 0

On what OS/arch does this happen?

> Time overflow tests...
> ```
> 
> Therefore, this patch adds some logs to make debugging easier.

We can add a bit of info, but...

> 
>  			if (time_cmp != asn1_cmp) {
> -				fprintf(stderr, "%s vs. %s: want %d, got %d\n",
> -				    att1->str, att2->str, time_cmp, asn1_cmp);
> +				fprintf(stderr, "test %d (ASN1_TIME_compare) - %s vs. %s: want %d, got %d\n",
> +				    i, att1->str, att2->str, time_cmp, asn1_cmp);
>  				comparison_failure |= 1;

I don't think it is super helpful to add 'test %d' to the output.
It is easy to determine what table the 'att1->str came from.

> @@ -624,9 +624,13 @@ asn1_time_compare_test(void)
>  	size_t utc_size = N_UTCTIME_TESTS;
>  	int failed = 0;
>  
> +	fprintf(stderr, "Time compare tests (gen, gen)...\n");
>  	failed |= asn1_time_compare_families(gen, gen_size, gen, gen_size);
> +	fprintf(stderr, "Time compare tests (gen, utc)...\n");
>  	failed |= asn1_time_compare_families(gen, gen_size, utc, utc_size);
> +	fprintf(stderr, "Time compare tests (utc, gen)...\n");
>  	failed |= asn1_time_compare_families(utc, utc_size, gen, gen_size);
> +	fprintf(stderr, "Time compare tests (utc, utc)...\n");
>  	failed |= asn1_time_compare_families(utc, utc_size, utc, utc_size);

And this is too much in my opinion. The test is already too noisy.

I'd suggest we keep this part of your diff:

Index: asn1time.c
===================================================================
RCS file: /cvs/src/regress/lib/libcrypto/asn1/asn1time.c,v
diff -u -p -r1.29 asn1time.c
--- asn1time.c	25 May 2024 18:59:03 -0000	1.29
+++ asn1time.c	21 Jul 2024 10:25:18 -0000
@@ -581,14 +581,16 @@ asn1_time_compare_families(const struct 
 			asn1_cmp = ASN1_TIME_compare(t1, t2);
 
 			if (time_cmp != asn1_cmp) {
-				fprintf(stderr, "%s vs. %s: want %d, got %d\n",
+				fprintf(stderr, "ASN1_TIME_compare - %s vs. %s: "
+				    "want %d, got %d\n",
 				    att1->str, att2->str, time_cmp, asn1_cmp);
 				comparison_failure |= 1;
 			}
 
 			time_cmp = ASN1_TIME_cmp_time_t(t1, att2->time);
 			if (time_cmp != asn1_cmp) {
-				fprintf(stderr, "%s vs. %lld: want %d, got %d\n",
+				fprintf(stderr, "ASN1_TIME_cmp_time_t - %s vs. %lld: "
+				    "want %d, got %d\n",
 				    att1->str, (long long)att2->time,
 				    asn1_cmp, time_cmp);
 				comparison_failure |= 1;
@@ -598,7 +600,8 @@ asn1_time_compare_families(const struct 
 			if (t1->type != V_ASN1_UTCTIME)
 				asn1_cmp = -2;
 			if (time_cmp != asn1_cmp) {
-				fprintf(stderr, "%s vs. %lld: want %d, got %d\n",
+				fprintf(stderr, "ASN1_UTCTIME_cmp_time_t - %s vs. %lld: "
+				    "want %d, got %d\n",
 				    att1->str, (long long)att2->time,
 				    asn1_cmp, time_cmp);
 				comparison_failure |= 1;