apps/openssl.c: Adapt to enable tracing output

Use the environment variables OPENSSL_TRACE to determine what's going
to be enabled.  The value of this variables is a comma separated list
of trace and debugging names, which correspond to the trace category
macros defined in include/openssl/trace.h.

For example, setting OPENSSL_DEBUG=TRACE,SSL will enable debugging output
for the types OSSL_TRACE_CATEGORY_TRACE and OSSL_TRACE_CATEGORY_SSL.

This also slightly changes the handling of the prefix method in
apps/apps.c.  This is for the better, as the prefix method pointer was
unneccessarily stored in two places.

Co-authored-by: Dr. Matthias St. Pierre <Matthias.St.Pierre@ncp-e.com>

Reviewed-by: Paul Dale <paul.dale@oracle.com>
(Merged from https://github.com/openssl/openssl/pull/8198)

apps/apps.c

@@ -2243,8 +2243,6 @@ BIO *dup_bio_in(int format)
                       BIO_NOCLOSE | (FMT_istext(format) ? BIO_FP_TEXT : 0));
 }
 
-static BIO_METHOD *prefix_method = NULL;
-
 BIO *dup_bio_out(int format)
 {
     BIO *b = BIO_new_fp(stdout,
@@ -2256,10 +2254,9 @@ BIO *dup_bio_out(int format)
         b = BIO_push(BIO_new(BIO_f_linebuffer()), b);
 #endif
 
-    if (FMT_istext(format) && (prefix = getenv("HARNESS_OSSL_PREFIX")) != NULL) {
-        if (prefix_method == NULL)
-            prefix_method = apps_bf_prefix();
-        b = BIO_push(BIO_new(prefix_method), b);
+    if (FMT_istext(format)
+        && (prefix = getenv("HARNESS_OSSL_PREFIX")) != NULL) {
+        b = BIO_push(BIO_new(apps_bf_prefix()), b);
         BIO_ctrl(b, PREFIX_CTRL_SET_PREFIX, 0, prefix);
     }
 
@@ -2277,8 +2274,13 @@ BIO *dup_bio_err(int format)
     return b;
 }
 
+/*
+ * Because the prefix method is created dynamically, we must also be able
+ * to destroy it.
+ */
 void destroy_prefix_method(void)
 {
+    BIO_METHOD *prefix_method = apps_bf_prefix();
     BIO_meth_free(prefix_method);
     prefix_method = NULL;
 }

apps/openssl.c

@@ -13,6 +13,7 @@
 #include <stdlib.h>
 #include <openssl/bio.h>
 #include <openssl/crypto.h>
+#include <openssl/trace.h>
 #include <openssl/lhash.h>
 #include <openssl/conf.h>
 #include <openssl/x509.h>
@@ -93,7 +94,6 @@ static int apps_startup(void)
 static void apps_shutdown(void)
 {
     destroy_ui_method();
-    destroy_prefix_method();
 }
 
 static char *make_config_name(void)
@@ -117,6 +117,89 @@ static char *make_config_name(void)
     return p;
 }
 
+typedef struct tracedata_st {
+    BIO *bio;
+    unsigned int ingroup:1;
+} tracedata;
+
+static size_t internal_trace_cb(const char *buf, size_t cnt,
+                                int category, int cmd, void *vdata)
+{
+    int ret;
+    tracedata *trace_data = vdata;
+    int set_prefix = 0;
+
+    switch (cmd) {
+    case OSSL_TRACE_CTRL_BEGIN:
+        trace_data->ingroup = 1;
+        set_prefix = 1;
+        break;
+    case OSSL_TRACE_CTRL_DURING:
+        if (!trace_data->ingroup)
+            set_prefix = 1;
+        break;
+    case OSSL_TRACE_CTRL_END:
+        trace_data->ingroup = 0;
+        break;
+    }
+
+    if (set_prefix) {
+        union {
+            CRYPTO_THREAD_ID tid;
+            unsigned long ltid;
+        } tid;
+        char buffer[256];
+
+        tid.ltid = 0;
+        tid.tid = CRYPTO_THREAD_get_current_id();
+
+        BIO_snprintf(buffer, sizeof(buffer), "TRACE[%lx]:%s: ", tid.ltid,
+                     OSSL_trace_get_category_name(category));
+        BIO_ctrl(trace_data->bio, PREFIX_CTRL_SET_PREFIX,
+                 strlen(buffer), buffer);
+    }
+    ret = BIO_write(trace_data->bio, buf, cnt);
+
+    return ret < 0 ? 0 : ret;
+}
+
+static void setup_trace(const char *str)
+{
+    char *val;
+
+    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 >= 0) {
+                BIO *channel = BIO_push(BIO_new(apps_bf_prefix()),
+                                        dup_bio_err(FORMAT_TEXT));
+                tracedata *trace_data = OPENSSL_zalloc(sizeof(*trace_data));
+
+                if (trace_data == NULL
+                    || (trace_data->bio = channel) == NULL
+                    || OSSL_trace_set_callback(category, internal_trace_cb,
+                                               trace_data) == 0) {
+                    fprintf(stderr,
+                            "warning: unable to setup trace callback for category '%s'.\n",
+                            item);
+                }
+            } else {
+                fprintf(stderr,
+                        "warning: unknown trace category: '%s'.\n",
+                        item);
+            }
+        }
+    }
+
+    OPENSSL_free(val);
+}
+
 int main(int argc, char *argv[])
 {
     FUNCTION f, *fp;
@@ -145,6 +228,15 @@ int main(int argc, char *argv[])
     win32_utf8argv(&argc, &argv);
 #endif
 
+    /*
+     * We use the prefix method to get the trace output we want.  Since some
+     * trace outputs happen with OPENSSL_cleanup(), which is run automatically
+     * after exit(), we need to destroy the prefix method as late as possible.
+     */
+    atexit(destroy_prefix_method);
+
+    setup_trace(getenv("OPENSSL_TRACE"));
+
     p = getenv("OPENSSL_DEBUG_MEMORY");
     if (p != NULL && strcmp(p, "on") == 0)
         CRYPTO_set_mem_debug(1);