DECODER & ENCODER: Add better tracing

Now that we have functions to get the name and properties of the
diverse implementations, we can as well display them for clarity.

Reviewed-by: Tomas Mraz <tomas@openssl.org>
Reviewed-by: Matt Caswell <matt@openssl.org>
(Merged from https://github.com/openssl/openssl/pull/15498)

3 files changed, 71 insertions, 16 deletions

diff --git a/crypto/encode_decode/decoder_lib.c b/crypto/encode_decode/decoder_lib.c
index cb3fe6af6a..eb90a9eaf5 100644
--- a/crypto/encode_decode/decoder_lib.c
+++ b/crypto/encode_decode/decoder_lib.c
@@ -288,11 +288,11 @@ int ossl_decoder_ctx_add_decoder_inst(OSSL_DECODER_CTX *ctx,
     if (ok) {
         OSSL_TRACE_BEGIN(DECODER) {
             BIO_printf(trc_out,
-                       "(ctx %p) Added decoder instance %p (decoder %p) with:\n",
-                       (void *)ctx, (void *)di, (void *)di->decoder);
-            BIO_printf(trc_out,
-                       "    input type: %s, input structure: %s\n",
-                       di->input_type, di->input_structure);
+                       "(ctx %p) Added decoder instance %p for decoder %p\n"
+                       "    %s with %s\n",
+                       (void *)ctx, (void *)di, (void *)di->decoder,
+                       OSSL_DECODER_get0_name(di->decoder),
+                       OSSL_DECODER_get0_properties(di->decoder));
         } OSSL_TRACE_END(DECODER);
     }
     return ok;
@@ -354,6 +354,15 @@ static void collect_extra_decoder(OSSL_DECODER *decoder, void *arg)
         void *decoderctx = NULL;
         OSSL_DECODER_INSTANCE *di = NULL;
 
+        OSSL_TRACE_BEGIN(DECODER) {
+            BIO_printf(trc_out,
+                       "(ctx %p) [%d] Checking out decoder %p:\n"
+                       "    %s with %s\n",
+                       (void *)data->ctx, data->type_check, (void *)decoder,
+                       OSSL_DECODER_get0_name(decoder),
+                       OSSL_DECODER_get0_properties(decoder));
+        } OSSL_TRACE_END(DECODER);
+
         /*
          * Check that we don't already have this decoder in our stack,
          * starting with the previous windows but also looking at what
@@ -363,9 +372,14 @@ static void collect_extra_decoder(OSSL_DECODER *decoder, void *arg)
             OSSL_DECODER_INSTANCE *check_inst =
                 sk_OSSL_DECODER_INSTANCE_value(data->ctx->decoder_insts, j);
 
-            if (decoder->base.algodef == check_inst->decoder->base.algodef)
+            if (decoder->base.algodef == check_inst->decoder->base.algodef) {
                 /* We found it, so don't do anything more */
+                OSSL_TRACE_BEGIN(DECODER) {
+                    BIO_printf(trc_out,
+                               "    REJECTED: already exists in the chain\n");
+                } OSSL_TRACE_END(DECODER);
                 return;
+            }
         }
 
         if ((decoderctx = decoder->newctx(provctx)) == NULL)
@@ -382,6 +396,10 @@ static void collect_extra_decoder(OSSL_DECODER *decoder, void *arg)
             if (!OSSL_DECODER_is_a(decoder,
                                    OSSL_DECODER_INSTANCE_get_input_type(di))) {
                 ossl_decoder_instance_free(di);
+                OSSL_TRACE_BEGIN(DECODER) {
+                    BIO_printf(trc_out,
+                               "    REJECTED: input type doesn't match output type\n");
+                } OSSL_TRACE_END(DECODER);
                 return;
             }
             break;
@@ -390,6 +408,10 @@ static void collect_extra_decoder(OSSL_DECODER *decoder, void *arg)
             if (OSSL_DECODER_is_a(decoder,
                                   OSSL_DECODER_INSTANCE_get_input_type(di))) {
                 ossl_decoder_instance_free(di);
+                OSSL_TRACE_BEGIN(DECODER) {
+                    BIO_printf(trc_out,
+                               "    REJECTED: input type matches output type\n");
+                } OSSL_TRACE_END(DECODER);
                 return;
             }
             break;
@@ -450,6 +472,11 @@ int OSSL_DECODER_CTX_add_extra(OSSL_DECODER_CTX *ctx,
     if (ctx->decoder_insts == NULL)
         return 1;
 
+    OSSL_TRACE_BEGIN(DECODER) {
+        BIO_printf(trc_out, "(ctx %p) Looking for extra decoders\n",
+                   (void *)ctx);
+    } OSSL_TRACE_END(DECODER);
+
     memset(&data, 0, sizeof(data));
     data.ctx = ctx;
     data.w_prev_start = 0;
@@ -667,7 +694,21 @@ static int decoder_process(const OSSL_PARAM params[], void *arg)
 
         data->flag_construct_called = 0;
         if (ctx->construct != NULL) {
-            int rv = ctx->construct(decoder_inst, params, ctx->construct_data);
+            int rv;
+
+            OSSL_TRACE_BEGIN(DECODER) {
+                BIO_printf(trc_out,
+                           "(ctx %p) %s Running constructor\n",
+                           (void *)new_data.ctx, LEVEL);
+            } OSSL_TRACE_END(DECODER);
+
+            rv = ctx->construct(decoder_inst, params, ctx->construct_data);
+
+            OSSL_TRACE_BEGIN(DECODER) {
+                BIO_printf(trc_out,
+                           "(ctx %p) %s Running constructor => %d\n",
+                           (void *)new_data.ctx, LEVEL, rv);
+            } OSSL_TRACE_END(DECODER);
 
             data->flag_construct_called = 1;
             ok = (rv > 0);
@@ -763,11 +804,12 @@ static int decoder_process(const OSSL_PARAM params[], void *arg)
 
         OSSL_TRACE_BEGIN(DECODER) {
             BIO_printf(trc_out,
-                       "(ctx %p) %s [%u] Considering decoder instance %p, which has:\n"
-                       "    input type: %s, input structure: %s, decoder: %p\n",
+                       "(ctx %p) %s [%u] Considering decoder instance %p (decoder %p):\n"
+                       "    %s with %s\n",
                        (void *)new_data.ctx, LEVEL, (unsigned int)i,
-                       (void *)new_decoder_inst, new_input_type,
-                       new_input_structure, (void *)new_decoder);
+                       (void *)new_decoder_inst, (void *)new_decoder,
+                       OSSL_DECODER_get0_name(new_decoder),
+                       OSSL_DECODER_get0_properties(new_decoder));
         } OSSL_TRACE_END(DECODER);
 
         /*
diff --git a/crypto/encode_decode/decoder_pkey.c b/crypto/encode_decode/decoder_pkey.c
index c9ccb2200a..cdd9841ea9 100644
--- a/crypto/encode_decode/decoder_pkey.c
+++ b/crypto/encode_decode/decoder_pkey.c
@@ -265,7 +265,20 @@ static void collect_decoder(OSSL_DECODER *decoder, void *arg)
                 return;
             }
 
+            OSSL_TRACE_BEGIN(DECODER) {
+                BIO_printf(trc_out,
+                           "(ctx %p) Checking out decoder %p:\n"
+                           "    %s with %s\n",
+                           (void *)data->ctx, (void *)decoder,
+                           OSSL_DECODER_get0_name(decoder),
+                           OSSL_DECODER_get0_properties(decoder));
+            } OSSL_TRACE_END(DECODER);
+
             if (!decoder_check_input_structure(data->ctx, di)) {
+                OSSL_TRACE_BEGIN(DECODER) {
+                    BIO_printf(trc_out,
+                               "    REJECTED: not the desired input structure\n");
+                } OSSL_TRACE_END(DECODER);
                 ossl_decoder_instance_free(di);
                 /* Not a fatal error. Just return */
                 return;
diff --git a/crypto/encode_decode/encoder_lib.c b/crypto/encode_decode/encoder_lib.c
index cb47e8bc71..6c20fbb3d1 100644
--- a/crypto/encode_decode/encoder_lib.c
+++ b/crypto/encode_decode/encoder_lib.c
@@ -265,11 +265,11 @@ static int ossl_encoder_ctx_add_encoder_inst(OSSL_ENCODER_CTX *ctx,
     if (ok) {
         OSSL_TRACE_BEGIN(ENCODER) {
             BIO_printf(trc_out,
-                       "(ctx %p) Added encoder instance %p (encoder %p) with:\n",
-                       (void *)ctx, (void *)ei, (void *)ei->encoder);
-            BIO_printf(trc_out,
-                       "    output type: %s, output structure: %s\n",
-                       ei->output_type, ei->output_structure);
+                       "(ctx %p) Added encoder instance %p (encoder %p):\n"
+                       "    %s with %s\n",
+                       (void *)ctx, (void *)ei, (void *)ei->encoder,
+                       OSSL_ENCODER_get0_name(ei->encoder),
+                       OSSL_ENCODER_get0_properties(ei->encoder));
         } OSSL_TRACE_END(ENCODER);
     }
     return ok;