enhance trace API adding verbosity levels and automatic func+file+line output by DDvO · Pull Request #9110 · openssl/openssl

DDvO · 2019-06-07T14:43:18Z

This is a by-product of the CMP contribution. As discussed with @mattcaswell for the preview of chunk 4: mpeylo#178 (comment) I've carved this out as an independent PR. It is going to be used first in #9107.

This adds

severity/verbosity levels per category: alert/error/warning/info/debug/trace
automatic output of function name, file name, line number, and severity level to the trace API.

I have not yet updated the documentation files accordingly because I thought it would be more efficient to collect some feedback, decide on any further changes, and then implement them along with the due extensions of the respective .pod files.

The use of the severity level functions should be self-explanatory.
Log messages can be produced like this:

OSSL_TRACE(TLS, "message with default severity level"); /* as before, backward compatsible */
OSSL_TRACEV(TLS, INFO, (trc_out, "this is a TLS %s message\n", "info")); /* with explicit level etc. */
OSSL_CMP_info("this is a CMP info message"); /* using include/openssl/cmp_util.h */

The output, as far as enabled according to the level, looks like this:

my_function:test/my_file.c:103:INFO:this is a CMP info message

It turns out that the trace facility of OpenSSL is disabled globally by default and needs to be enabled explicitly via the enable-trace configuration option. This is not adequate when using the trace API for error and warning output.
What I propose instead is to enable its inclusion by default (as done in this PR in Configiure)
while taking, e.g., OSSL_TRACE_LEVEL_INFO as the default level of verbosity. In this way detailed (trace-level and debugging) output remains disabled while alert, error, warning, and info output is enabled.
When DEBUG is defined and NDEBUG is not defined, the default becomes OSSL_TRACE_LEVEL_DEBUG.
Using the new code in trace.h and trace.c, the level of verbosity can be adapted per category.

documentation is added or updated

… output

mspncp

Thank you for your enhancements to the trace api. When the trace api was introduced, I also considered having trace categories and trace levels. But then I discarded the idea again because I thought the classification might be too fine grained. But if you think it's a useful feature, I don't mind.

There are however some details about your implementation which I dislike. It's mostly about consistency of naming and of implementation.

First of all, please be consistent with your naming: Either call it "trace level" or "trace verbosity", but not both. (I prefer the former.) So the function should be named

const char *OSSL_trace_get_level_name(int level)

Also, I don't see the inverse function.

int OSSL_trace_get_level_num(const char *name)

In fact, there is absolutely no reason to implement those two functions completely differently than the existing functions

const char *OSSL_trace_get_category_name(int num);
int OSSL_trace_get_category_num(const char *name);

The implementations can be made completely analogous, it's just copy&paste&rename of the following code, then add your level names.

openssl/crypto/trace.c

Lines 114 to 155 in 37ca204

    
           /* Helper struct and macro to get name string to number mapping */ 
        
           struct trace_category_st { 
        
               const char * const name; 
        
               const int num; 
        
           }; 
        
           #define TRACE_CATEGORY_(name)       { #name, OSSL_TRACE_CATEGORY_##name } 
        
           static const struct trace_category_st trace_categories[] = { 
        
               TRACE_CATEGORY_(ALL), 
        
               TRACE_CATEGORY_(TRACE), 
        
               TRACE_CATEGORY_(INIT), 
        
               TRACE_CATEGORY_(TLS), 
        
               TRACE_CATEGORY_(TLS_CIPHER), 
        
               TRACE_CATEGORY_(CONF), 
        
               TRACE_CATEGORY_(ENGINE_TABLE), 
        
               TRACE_CATEGORY_(ENGINE_REF_COUNT), 
        
               TRACE_CATEGORY_(PKCS5V2), 
        
               TRACE_CATEGORY_(PKCS12_KEYGEN), 
        
               TRACE_CATEGORY_(PKCS12_DECRYPT), 
        
               TRACE_CATEGORY_(X509V3_POLICY), 
        
               TRACE_CATEGORY_(BN_CTX), 
        
           }; 
        
           const char *OSSL_trace_get_category_name(int num) 
        
           { 
        
               size_t i; 
        
               for (i = 0; i < OSSL_NELEM(trace_categories); i++) 
        
                   if (trace_categories[i].num == num) 
        
                       return trace_categories[i].name; 
        
               return NULL; /* not found */ 
        
           } 
        
           int OSSL_trace_get_category_num(const char *name) 
        
           { 
        
               size_t i; 
        
               for (i = 0; i < OSSL_NELEM(trace_categories); i++) 
        
                   if (strcasecmp(name, trace_categories[i].name) == 0) 
        
                       return trace_categories[i].num; 
        
               return -1; /* not found */ 
        
           }

And most importantly: adding an api for the trace level, but completely neglecting the level parameter in the OSSL_TRACEX(...) convenience macros is an absolute no-go. If it's a useful parameter, then it MUST be available through the macros, too.

mspncp · 2019-06-07T15:33:36Z

crypto/trace.c

 #endif
 }

+const char *OSSL_trace_get_verbosity_name(int level)


It should be called

const char *OSSL_trace_get_level_name(int level)

in order to be consistent with the names of the constants.

mspncp · 2019-06-07T16:05:57Z

include/openssl/trace.h

+ * TRACE LEVEL AND VERBOSITY
+ */
+
+# define OSSL_TRACE_LEVEL_UNDEFINED     0


I see no use in having an 'undefined' trace level. Normally, I would call it 'off' or 'disabled', but since trace categories are enabled by attaching channels to them, a 'disabled' level does not make sense IMHO.

mspncp · 2019-06-07T16:09:53Z

include/openssl/trace.h


 # define OSSL_TRACE(category, text) \
-    OSSL_TRACEV(category, (trc_out, "%s", text))
+    OSSL_TRACEV(category, UNDEFINED, (trc_out, "%s", text))


The trace level MUST be part of the trace macros, too. Otherwise, the addition of trace levels does not make sense.

mspncp · 2019-06-07T16:33:49Z

include/openssl/trace.h

+# if defined DEBUG && !defined NDEBUG
+#  define OSSL_TRACE_LEVEL_DEFAULT      OSSL_TRACE_LEVEL_DEBUG
+# else
+#  define OSSL_TRACE_LEVEL_DEFAULT      OSSL_TRACE_LEVEL_INFO


Please use 'info' as default level regardless of DEBUG/NDEBUG.

mspncp · 2019-06-07T16:36:44Z

Please also note that the OPENSSL(1) command supports setting the trace categories via environment variable.

      OPENSSL_TRACE=name,...
           Enable tracing output of OpenSSL library, by name.  This output will only make sense if you know OpenSSL internals well.  Also, it might
           not give you any output at all, depending on how OpenSSL was built.

           The value is a comma separated list of names, with the following available:

           TRACE
               The tracing functionality.

           TLS General SSL/TLS.

           TLS_CIPHER
               SSL/TLS cipher.

		   ...

I don't think it is necessary to enhance the syntax of the OPENSSL_TRACE ~~macro~~ environment variable. You just need to ensure that the trace level for the enabled categories is set to the default level.

For a starting point, see

openssl/apps/openssl.c

Lines 215 to 240 in 37ca204

    
           static void setup_trace(const char *str) 
        
           { 
        
               char *val; 
        
               trace_data_stack = sk_tracedata_new_null(); 
        
               val = OPENSSL_strdup(str); 
        
               if (val != NULL) { 
        
                   char *valp = val; 
        
                   char *item; 
        
                   for (valp = val; (item = strtok(valp, ",")) != NULL; valp = NULL) { 
        
                       int category = OSSL_trace_get_category_num(item); 
        
                       if (category == OSSL_TRACE_CATEGORY_ALL) { 
        
                           while (++category < OSSL_TRACE_CATEGORY_NUM) 
        
                               setup_trace_category(category); 
        
                           break; 
        
                       } else if (category > 0) { 
        
                           setup_trace_category(category); 
        
                       } else { 
        
                           fprintf(stderr, 
        
                                   "warning: unknown trace category: '%s'.\n", item); 
        
                       } 
        
                   } 
        
               }

mspncp · 2019-06-07T16:49:29Z

Configure

                  "ssl-trace"           => "default",
                  "ssl3"                => "default",
                  "ssl3-method"         => "default",
-                  "trace"               => "default",


The trace api is disabled by default for good reasons, see 6bc62a6, #8474 and #8472. Please don't change that.

I would accept if 'debug' woud imply 'trace', but I don't see a precedent in the Configure file, i.e., there is no @enable_cascades analogous to @disable_cascades.

openssl/Configure

Lines 474 to 478 in 2c8a407

my @disable_cascades = (

# "what" => [ "cascade", ... ]

sub { $config{processor} eq "386" }

=> [ "sse2" ],

"ssl" => [ "ssl3" ],

I would accept if 'debug' would imply 'trace'

I'm not even sure whether such an automatism needs to be added at all. Since most people either rely on command line history or have personal configure scripts, the trace option can easily be added to the command line.

DO NOT ENABLE TRACE BY DEFAULT.

Thank you for this feedback.
David is on vacation the next two weeks, but he will change this as soon as possible.

No hurry. I‘ll be on vacation, too.

… requested

DDvO · 2019-06-25T07:07:54Z

I had already started doing the requested changes, but meanwhile I wonder if its is worth continuing.

As mentioned, due to the trace facility being disabled in default/production builds,
it is in fact pointless for the purpose I've been using it for the upcoming CMP library component,
where some diagnostic output like warnings are meant for user attention and/or logging (where the output is strongly configurable by a callback, with the default being plain console printing).

What do you (all) think, should we nevertheless continue as indicated above, for potential benefit to other parts/users of libcrypto?

DDvO · 2019-06-25T07:10:00Z

BTW, this PR is also related to #9058.

DDvO · 2019-07-09T07:40:58Z

As mentioned above and discussed about two weeks ago in the context of the CMP contribution chunk 4:
#9107 (comment)
it turned out that this PR does not have sufficient relevance, at least for now, so I've just closed it.
In case it turns out to be of interest later, I suppose it could be re-opened.

enhance trace API adding verbosity level and automatic func+file+line…

2c8a407

… output

DDvO mentioned this pull request Jun 7, 2019

WIP: Preview of CMP implementation, incremental PR chunk 4: CMP context/parameters mpeylo/cmpossl#178

Closed

2 tasks

mspncp suggested changes Jun 7, 2019

View reviewed changes

mspncp reviewed Jun 7, 2019

View reviewed changes

DDvO added 3 commits June 9, 2019 10:18

disable trace facility by default again as demanded by reviewers

846645c

use OSSL_TRACE_LEVEL_DEFAULT = INFO regardless of DEBUG and NDEBUG as…

07a9f22

… requested

rename verbosity -> level

29db614

DDvO mentioned this pull request Jun 25, 2019

CMP implementation, incremental PR chunk 4: CMP context/parameters and utilities #9107

Closed

2 tasks

DDvO closed this Sep 25, 2019

	/* Helper struct and macro to get name string to number mapping */
	struct trace_category_st {
	const char * const name;
	const int num;
	};
	#define TRACE_CATEGORY_(name) { #name, OSSL_TRACE_CATEGORY_##name }

	static const struct trace_category_st trace_categories[] = {
	TRACE_CATEGORY_(ALL),
	TRACE_CATEGORY_(TRACE),
	TRACE_CATEGORY_(INIT),
	TRACE_CATEGORY_(TLS),
	TRACE_CATEGORY_(TLS_CIPHER),
	TRACE_CATEGORY_(CONF),
	TRACE_CATEGORY_(ENGINE_TABLE),
	TRACE_CATEGORY_(ENGINE_REF_COUNT),
	TRACE_CATEGORY_(PKCS5V2),
	TRACE_CATEGORY_(PKCS12_KEYGEN),
	TRACE_CATEGORY_(PKCS12_DECRYPT),
	TRACE_CATEGORY_(X509V3_POLICY),
	TRACE_CATEGORY_(BN_CTX),
	};

	const char *OSSL_trace_get_category_name(int num)
	{
	size_t i;

	for (i = 0; i < OSSL_NELEM(trace_categories); i++)
	if (trace_categories[i].num == num)
	return trace_categories[i].name;
	return NULL; /* not found */
	}

	int OSSL_trace_get_category_num(const char *name)
	{
	size_t i;

	for (i = 0; i < OSSL_NELEM(trace_categories); i++)
	if (strcasecmp(name, trace_categories[i].name) == 0)
	return trace_categories[i].num;
	return -1; /* not found */
	}

	my @disable_cascades = (
	# "what" => [ "cascade", ... ]
	sub { $config{processor} eq "386" }
	=> [ "sse2" ],
	"ssl" => [ "ssl3" ],

Uh oh!

Conversation

DDvO commented Jun 7, 2019

Uh oh!

mspncp left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mspncp commented Jun 7, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

DDvO commented Jun 25, 2019

Uh oh!

DDvO commented Jun 25, 2019

Uh oh!

DDvO commented Jul 9, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

mspncp left a comment •

edited

Loading

mspncp commented Jun 7, 2019 •

edited

Loading