From: Richard Levitte Date: Fri, 19 Feb 2021 09:16:04 +0000 (+0100) Subject: DECODER: Add better tracing of the chain walking process X-Git-Tag: openssl-3.0.0-alpha13~249 X-Git-Url: https://git.openssl.org/gitweb/?p=openssl.git;a=commitdiff_plain;h=57acc56bdcdf2a7f084cf480f6f1d8f250735b0c DECODER: Add better tracing of the chain walking process Reviewed-by: Matt Caswell Reviewed-by: Paul Dale (Merged from https://github.com/openssl/openssl/pull/14233) --- diff --git a/crypto/encode_decode/decoder_lib.c b/crypto/encode_decode/decoder_lib.c index 724c455b6d..6503b46d63 100644 --- a/crypto/encode_decode/decoder_lib.c +++ b/crypto/encode_decode/decoder_lib.c @@ -28,6 +28,8 @@ struct decoder_process_data_st { /* Index of the current decoder instance to be processed */ size_t current_decoder_inst_index; + /* For tracing, count recursion level */ + size_t recursion; }; static int decoder_process(const OSSL_PARAM params[], void *arg); @@ -517,16 +519,29 @@ static int decoder_process(const OSSL_PARAM params[], void *arg) memset(&new_data, 0, sizeof(new_data)); new_data.ctx = data->ctx; + new_data.recursion = data->recursion + 1; + +#define LEVEL_STR ">>>>>>>>>>>>>>>>" +#define LEVEL (new_data.recursion < sizeof(LEVEL_STR) \ + ? &LEVEL_STR[sizeof(LEVEL_STR) - new_data.recursion - 1] \ + : LEVEL_STR "...") if (params == NULL) { /* First iteration, where we prepare for what is to come */ + OSSL_TRACE_BEGIN(DECODER) { + BIO_printf(trc_out, + "(ctx %p) starting to walk the decoder chain\n", + (void *)new_data.ctx); + } OSSL_TRACE_END(DECODER); + data->current_decoder_inst_index = OSSL_DECODER_CTX_get_num_decoders(ctx); bio = data->bio; } else { const OSSL_PARAM *p; + const char *trace_data_structure; decoder_inst = sk_OSSL_DECODER_INSTANCE_value(ctx->decoder_insts, @@ -578,9 +593,20 @@ static int decoder_process(const OSSL_PARAM params[], void *arg) * There's only so much you can do without infusing this code with * too special knowledge. */ + trace_data_structure = data_structure; if (data_type != NULL && strcasecmp(data_structure, "type-specific") == 0) data_structure = NULL; + + OSSL_TRACE_BEGIN(DECODER) { + BIO_printf(trc_out, + "(ctx %p) %s incoming from previous decoder (%p):\n" + " data type: %s, data structure: %s%s\n", + (void *)new_data.ctx, LEVEL, (void *)decoder, + data_type, trace_data_structure, + (trace_data_structure == data_structure + ? "" : " (dropped)")); + } OSSL_TRACE_END(DECODER); } /* @@ -609,14 +635,30 @@ static int decoder_process(const OSSL_PARAM params[], void *arg) OSSL_DECODER_INSTANCE_get_input_structure(new_decoder_inst, &n_i_s_was_set); + 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", + (void *)new_data.ctx, LEVEL, (unsigned int)i, + (void *)new_decoder_inst, new_input_type, + new_input_structure, (void *)new_decoder); + } OSSL_TRACE_END(DECODER); + /* * If |decoder| is NULL, it means we've just started, and the caller * may have specified what it expects the initial input to be. If * that's the case, we do this extra check. */ if (decoder == NULL && ctx->start_input_type != NULL - && strcasecmp(ctx->start_input_type, new_input_type) != 0) + && strcasecmp(ctx->start_input_type, new_input_type) != 0) { + OSSL_TRACE_BEGIN(DECODER) { + BIO_printf(trc_out, + "(ctx %p) %s [%u] the start input type '%s' doesn't match the input type of the considered decoder, skipping...\n", + (void *)new_data.ctx, LEVEL, (unsigned int)i, + ctx->start_input_type); + } OSSL_TRACE_END(DECODER); continue; + } /* * If we have a previous decoder, we check that the input type @@ -624,15 +666,28 @@ static int decoder_process(const OSSL_PARAM params[], void *arg) * |new_input_type| holds the value of the "input-type" parameter * for the decoder we're currently considering. */ - if (decoder != NULL && !OSSL_DECODER_is_a(decoder, new_input_type)) + if (decoder != NULL && !OSSL_DECODER_is_a(decoder, new_input_type)) { + OSSL_TRACE_BEGIN(DECODER) { + BIO_printf(trc_out, + "(ctx %p) %s [%u] the input type doesn't match the name of the previous decoder (%p), skipping...\n", + (void *)new_data.ctx, LEVEL, (unsigned int)i, + (void *)decoder); + } OSSL_TRACE_END(DECODER); continue; + } /* * If the previous decoder gave us a data type, we check to see * if that matches the decoder we're currently considering. */ - if (data_type != NULL && !OSSL_DECODER_is_a(new_decoder, data_type)) + if (data_type != NULL && !OSSL_DECODER_is_a(new_decoder, data_type)) { + OSSL_TRACE_BEGIN(DECODER) { + BIO_printf(trc_out, + "(ctx %p) %s [%u] the previous decoder's data type doesn't match the name of the considered decoder, skipping...\n", + (void *)new_data.ctx, LEVEL, (unsigned int)i); + } OSSL_TRACE_END(DECODER); continue; + } /* * If the previous decoder gave us a data structure name, we check @@ -641,8 +696,14 @@ static int decoder_process(const OSSL_PARAM params[], void *arg) */ if (data_structure != NULL && (new_input_structure == NULL - || strcasecmp(data_structure, new_input_structure) != 0)) + || strcasecmp(data_structure, new_input_structure) != 0)) { + OSSL_TRACE_BEGIN(DECODER) { + BIO_printf(trc_out, + "(ctx %p) %s [%u] the previous decoder's data structure doesn't match the input structure of the considered decoder, skipping...\n", + (void *)new_data.ctx, LEVEL, (unsigned int)i); + } OSSL_TRACE_END(DECODER); continue; + } /* * Checking the return value of BIO_reset() or BIO_seek() is unsafe. @@ -659,6 +720,13 @@ static int decoder_process(const OSSL_PARAM params[], void *arg) goto end; /* Recurse */ + OSSL_TRACE_BEGIN(DECODER) { + BIO_printf(trc_out, + "(ctx %p) %s [%u] Running decoder instance %p\n", + (void *)new_data.ctx, LEVEL, (unsigned int)i, + (void *)new_decoder_inst); + } OSSL_TRACE_END(DECODER); + new_data.current_decoder_inst_index = i; ok = new_decoder->decode(new_decoderctx, (OSSL_CORE_BIO *)bio, new_data.ctx->selection, @@ -668,8 +736,9 @@ static int decoder_process(const OSSL_PARAM params[], void *arg) OSSL_TRACE_BEGIN(DECODER) { BIO_printf(trc_out, - "(ctx %p) Running decoder instance %p => %d\n", - (void *)new_data.ctx, (void *)new_decoder_inst, ok); + "(ctx %p) %s [%u] Running decoder instance %p => %d\n", + (void *)new_data.ctx, LEVEL, (unsigned int)i, + (void *)new_decoder_inst, ok); } OSSL_TRACE_END(DECODER); if (ok)