Add QUERY trace points

Adds trace messages for method store add/remove and fetch operations

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

crypto/property/property.c

@@ -19,6 +19,7 @@
 #include "crypto/ctype.h"
 #include <openssl/lhash.h>
 #include <openssl/rand.h>
+#include <openssl/trace.h>
 #include "internal/thread_once.h"
 #include "crypto/lhash.h"
 #include "crypto/sparse_array.h"
@@ -288,6 +289,31 @@ static int ossl_method_store_insert(OSSL_METHOD_STORE *store, ALGORITHM *alg)
     return ossl_sa_ALGORITHM_set(store->algs, alg->nid, alg);
 }
 
+/**
+ * @brief Adds a method to the specified method store.
+ *
+ * This function adds a new method to the provided method store, associating it
+ * with a specified id, properties, and provider. The method is stored with
+ * reference count and destruction callbacks.
+ *
+ * @param store Pointer to the OSSL_METHOD_STORE where the method will be added.
+ *        must be non-null.
+ * @param prov Pointer to the OSSL_PROVIDER for the provider of the method.
+ *             Must be non-null.
+ * @param nid (identifier) associated with the method, must be > 0
+ * @param properties String containing properties of the method.
+ * @param method Pointer to the method to be added.
+ * @param method_up_ref Function pointer for incrementing the method ref count.
+ * @param method_destruct Function pointer for destroying the method.
+ *
+ * @return 1 if the method is successfully added, 0 on failure.
+ *
+ * If tracing is enabled, a message is printed indicating that the method is
+ * being added to the method store.
+ *
+ * NOTE: The nid parameter here is _not_ a nid in the sense of the NID_* macros.
+ * It is an internal unique identifier.
+ */
 int ossl_method_store_add(OSSL_METHOD_STORE *store, const OSSL_PROVIDER *prov,
                           int nid, const char *properties, void *method,
                           int (*method_up_ref)(void *),
@@ -300,6 +326,7 @@ int ossl_method_store_add(OSSL_METHOD_STORE *store, const OSSL_PROVIDER *prov,
 
     if (nid <= 0 || method == NULL || store == NULL)
         return 0;
+
     if (properties == NULL)
         properties = "";
 
@@ -324,7 +351,25 @@ int ossl_method_store_add(OSSL_METHOD_STORE *store, const OSSL_PROVIDER *prov,
         OPENSSL_free(impl);
         return 0;
     }
+
+    /*
+     * Flush the alg cache of any implementation that already exists
+     * for this id.
+     * This is done to ensure that on the next lookup we go through the
+     * provider comparison in ossl_method_store_fetch.  If we don't do this
+     * then this new method won't be given a chance to get selected.
+     * NOTE: This doesn't actually remove the method from the backing store
+     * It just ensures that we query the backing store when (re)-adding a
+     * method to the algorithm cache, in case the one selected by the next
+     * query selects a different implementation
+     */
     ossl_method_cache_flush(store, nid);
+
+    /*
+     * Parse the properties associated with this method, and convert it to a
+     * property list stored against the implementation for later comparison
+     * during fetch operations
+     */
     if ((impl->properties = ossl_prop_defn_get(store->ctx, properties)) == NULL) {
         impl->properties = ossl_parse_property(store->ctx, properties);
         if (impl->properties == NULL)
@@ -336,6 +381,10 @@ int ossl_method_store_add(OSSL_METHOD_STORE *store, const OSSL_PROVIDER *prov,
         }
     }
 
+    /*
+     * Check if we have an algorithm cache already for this nid.  If so use
+     * it, otherwise, create it, and insert it into the store
+     */
     alg = ossl_method_store_retrieve(store, nid);
     if (alg == NULL) {
         if ((alg = OPENSSL_zalloc(sizeof(*alg))) == NULL
@@ -353,11 +402,19 @@ int ossl_method_store_add(OSSL_METHOD_STORE *store, const OSSL_PROVIDER *prov,
 
         if (tmpimpl->provider == impl->provider
             && tmpimpl->properties == impl->properties)
-            break;
+            goto err;
     }
-    if (i == sk_IMPLEMENTATION_num(alg->impls)
+
-        && sk_IMPLEMENTATION_push(alg->impls, impl))
+    if (sk_IMPLEMENTATION_push(alg->impls, impl)) {
         ret = 1;
+        OSSL_TRACE_BEGIN(QUERY) {
+            BIO_printf(trc_out, "Adding to method store "
+                       "nid: %d\nproperties: %s\nprovider: %s\n",
+                       nid, properties,
+                       ossl_provider_name(prov) == NULL ? "none" :
+                       ossl_provider_name(prov));
+        } OSSL_TRACE_END(QUERY);
+    }
     ossl_property_unlock(store);
     if (ret == 0)
         impl_free(impl);
@@ -412,6 +469,21 @@ struct alg_cleanup_by_provider_data_st {
     const OSSL_PROVIDER *prov;
 };
 
+/**
+ * @brief Cleans up implementations of an algorithm associated with a provider.
+ *
+ * This function removes all implementations of a specified algorithm that are
+ * associated with a given provider. The function walks through the stack of
+ * implementations backwards to handle deletions without affecting indexing.
+ *
+ * @param idx Index of the algorithm (unused in this function).
+ * @param alg Pointer to the ALGORITHM structure containing the implementations.
+ * @param arg Pointer to the data containing the provider information.
+ *
+ * If tracing is enabled, messages are printed indicating the removal of each
+ * implementation and its properties. If any implementation is removed, the
+ * associated cache is flushed.
+ */
 static void
 alg_cleanup_by_provider(ossl_uintmax_t idx, ALGORITHM *alg, void *arg)
 {
@@ -426,9 +498,22 @@ alg_cleanup_by_provider(ossl_uintmax_t idx, ALGORITHM *alg, void *arg)
         IMPLEMENTATION *impl = sk_IMPLEMENTATION_value(alg->impls, i);
 
         if (impl->provider == data->prov) {
-            impl_free(impl);
+
+            OSSL_TRACE_BEGIN(QUERY) {
+                char buf[512];
+                size_t size;
+
+                size = ossl_property_list_to_string(NULL, impl->properties, buf, 512);
+                BIO_printf(trc_out, "Removing implementation from "
+                           "query cache\nproperties %s\nprovider %s\n",
+                           size == 0 ? "none" : buf,
+                           ossl_provider_name(impl->provider) == NULL ? "none" :
+                           ossl_provider_name(impl->provider));
+            } OSSL_TRACE_END(QUERY);
+
             (void)sk_IMPLEMENTATION_delete(alg->impls, i);
             count++;
+            impl_free(impl);
         }
     }
 
@@ -504,6 +589,29 @@ void ossl_method_store_do_all(OSSL_METHOD_STORE *store,
     }
 }
 
+/**
+ * @brief Fetches a method from the method store matching the given properties.
+ *
+ * This function searches the method store for an implementation of a specified
+ * method, identified by its id (nid), and matching the given property query. If
+ * successful, it returns the method and its associated provider.
+ *
+ * @param store Pointer to the OSSL_METHOD_STORE from which to fetch the method.
+ *        Must be non-null
+ * @param nid (identifier) of the method to be fetched. Must be > 0
+ * @param prop_query String containing the property query to match against.
+ * @param prov_rw Pointer to the OSSL_PROVIDER to restrict the search to, or
+ *                to receive the matched provider.
+ * @param method Pointer to receive the fetched method. Must be non-null.
+ *
+ * @return 1 if the method is successfully fetched, 0 on failure.
+ *
+ * If tracing is enabled, a message is printed indicating the property query and
+ * the resolved provider.
+ *
+ * NOTE: The nid parameter here is _not_ a NID in the sense of the NID_* macros.
+ * It is a unique internal identifier value.
+ */
 int ossl_method_store_fetch(OSSL_METHOD_STORE *store,
                             int nid, const char *prop_query,
                             const OSSL_PROVIDER **prov_rw, void **method)
@@ -528,14 +636,24 @@ int ossl_method_store_fetch(OSSL_METHOD_STORE *store,
     /* This only needs to be a read lock, because the query won't create anything */
     if (!ossl_property_read_lock(store))
         return 0;
+
     alg = ossl_method_store_retrieve(store, nid);
     if (alg == NULL) {
         ossl_property_unlock(store);
         return 0;
     }
 
+    /*
+     * If a property query string is provided, convert it to an
+     * OSSL_PROPERTY_LIST structure
+     */
     if (prop_query != NULL)
         p2 = pq = ossl_parse_query(store->ctx, prop_query, 0);
+
+    /*
+     * If the library context has default properties specified
+     * then merge those with the properties passed to this function
+     */
     plp = ossl_ctx_global_properties(store->ctx, 0);
     if (plp != NULL && *plp != NULL) {
         if (pq == NULL) {
@@ -549,6 +667,13 @@ int ossl_method_store_fetch(OSSL_METHOD_STORE *store,
         }
     }
 
+    /*
+     * Search for a provider that provides this implementation.
+     * if the requested provider is NULL, then any provider will do,
+     * otherwise we should try to find the one that matches the requested
+     * provider.  Note that providers are given implicit preference via the
+     * ordering of the implementation stack
+     */
     if (pq == NULL) {
         for (j = 0; j < sk_IMPLEMENTATION_num(alg->impls); j++) {
             if ((impl = sk_IMPLEMENTATION_value(alg->impls, j)) != NULL
@@ -560,6 +685,12 @@ int ossl_method_store_fetch(OSSL_METHOD_STORE *store,
         }
         goto fin;
     }
+
+    /*
+     * If there are optional properties specified
+     * the search again, and select the provider that matches the
+     * most options
+     */
     optional = ossl_property_has_optional(pq);
     for (j = 0; j < sk_IMPLEMENTATION_num(alg->impls); j++) {
         if ((impl = sk_IMPLEMENTATION_value(alg->impls, j)) != NULL
@@ -582,6 +713,19 @@ fin:
     } else {
         ret = 0;
     }
+
+    OSSL_TRACE_BEGIN(QUERY) {
+        char buf[512];
+        int size;
+
+        size = ossl_property_list_to_string(NULL, pq, buf, 512);
+        BIO_printf(trc_out, "method store query with properties %s "
+                   "resolves to provider %s\n",
+                   size == 0 ? "none" : buf,
+                   best_impl == NULL ? "none" :
+                   ossl_provider_name(best_impl->provider));
+    } OSSL_TRACE_END(QUERY);
+
     ossl_property_unlock(store);
     ossl_property_free(p2);
     return ret;

crypto/provider_core.c

@@ -1640,6 +1640,9 @@ static void trace_print_param_values(const OSSL_PARAM p[], BIO *b)
 {
     int64_t i;
     uint64_t u;
+# ifndef OPENSSL_SYS_UEFI
+    double d;
+# endif
 
     for (; p->key != NULL; p++) {
         BIO_printf(b, "%s: ", p->key);
@@ -1666,6 +1669,14 @@ static void trace_print_param_values(const OSSL_PARAM p[], BIO *b)
         case OSSL_PARAM_OCTET_STRING:
             BIO_printf(b, "<%zu bytes>\n", p->data_size);
             break;
+# ifndef OPENSSL_SYS_UEFI
+        case OSSL_PARAM_REAL:
+            if (OSSL_PARAM_get_double(p, &d))
+                BIO_printf(b, "%f\n", d);
+            else
+                BIO_printf(b, "error getting value\n");
+            break;
+# endif
         default:
             BIO_printf(b, "unknown type (%u) of %zu bytes\n",
                        p->data_type, p->data_size);

include/openssl/trace.h

@@ -58,9 +58,7 @@ extern "C" {
 # define OSSL_TRACE_CATEGORY_HTTP               18
 # define OSSL_TRACE_CATEGORY_PROVIDER           19
 # define OSSL_TRACE_CATEGORY_QUERY              20
-
+# define OSSL_TRACE_CATEGORY_NUM                21
-/* Count of available categories. */
-# define OSSL_TRACE_CATEGORY_NUM                21 
 /* KEEP THIS LIST IN SYNC with trace_categories[] in crypto/trace.c */
 
 /* Returns the trace category number for the given |name| */

test/trace_api_test.c

@@ -17,49 +17,67 @@ static int test_trace_categories(void)
 
     for (cat_num = -1; cat_num <= OSSL_TRACE_CATEGORY_NUM + 1; ++cat_num) {
         const char *cat_name = OSSL_trace_get_category_name(cat_num);
-        int is_cat_name_eq = 0;
+        const char *expected_cat_name = NULL;
         int ret_cat_num;
-        int expected_ret;
 
+#define SET_EXPECTED_CAT_NAME(name) expected_cat_name = #name; break
         switch (cat_num) {
-#define CASE(name) \
+        case OSSL_TRACE_CATEGORY_ALL:
-        case OSSL_TRACE_CATEGORY_##name: \
+            SET_EXPECTED_CAT_NAME(ALL);
-            is_cat_name_eq = TEST_str_eq(cat_name, #name); \
+        case OSSL_TRACE_CATEGORY_TRACE:
-            break
+            SET_EXPECTED_CAT_NAME(TRACE);
-
+        case OSSL_TRACE_CATEGORY_INIT:
-        CASE(ALL);
+            SET_EXPECTED_CAT_NAME(INIT);
-        CASE(TRACE);
+        case OSSL_TRACE_CATEGORY_TLS:
-        CASE(INIT);
+            SET_EXPECTED_CAT_NAME(TLS);
-        CASE(TLS);
+        case OSSL_TRACE_CATEGORY_TLS_CIPHER:
-        CASE(TLS_CIPHER);
+            SET_EXPECTED_CAT_NAME(TLS_CIPHER);
-        CASE(CONF);
+        case OSSL_TRACE_CATEGORY_CONF:
-        CASE(ENGINE_TABLE);
+            SET_EXPECTED_CAT_NAME(CONF);
-        CASE(ENGINE_REF_COUNT);
+        case OSSL_TRACE_CATEGORY_ENGINE_TABLE:
-        CASE(PKCS5V2);
+            SET_EXPECTED_CAT_NAME(ENGINE_TABLE);
-        CASE(PKCS12_KEYGEN);
+        case OSSL_TRACE_CATEGORY_ENGINE_REF_COUNT:
-        CASE(PKCS12_DECRYPT);
+            SET_EXPECTED_CAT_NAME(ENGINE_REF_COUNT);
-        CASE(X509V3_POLICY);
+        case OSSL_TRACE_CATEGORY_PKCS5V2:
-        CASE(BN_CTX);
+            SET_EXPECTED_CAT_NAME(PKCS5V2);
-        CASE(CMP);
+        case OSSL_TRACE_CATEGORY_PKCS12_KEYGEN:
-        CASE(STORE);
+            SET_EXPECTED_CAT_NAME(PKCS12_KEYGEN);
-        CASE(DECODER);
+        case OSSL_TRACE_CATEGORY_PKCS12_DECRYPT:
-        CASE(ENCODER);
+            SET_EXPECTED_CAT_NAME(PKCS12_DECRYPT);
-        CASE(REF_COUNT);
+        case OSSL_TRACE_CATEGORY_X509V3_POLICY:
-        CASE(HTTP);
+            SET_EXPECTED_CAT_NAME(X509V3_POLICY);
-        CASE(PROVIDER);
+        case OSSL_TRACE_CATEGORY_BN_CTX:
-#undef CASE
+            SET_EXPECTED_CAT_NAME(BN_CTX);
+        case OSSL_TRACE_CATEGORY_CMP:
+            SET_EXPECTED_CAT_NAME(CMP);
+        case OSSL_TRACE_CATEGORY_STORE:
+            SET_EXPECTED_CAT_NAME(STORE);
+        case OSSL_TRACE_CATEGORY_DECODER:
+            SET_EXPECTED_CAT_NAME(DECODER);
+        case OSSL_TRACE_CATEGORY_ENCODER:
+            SET_EXPECTED_CAT_NAME(ENCODER);
+        case OSSL_TRACE_CATEGORY_REF_COUNT:
+            SET_EXPECTED_CAT_NAME(REF_COUNT);
+        case OSSL_TRACE_CATEGORY_HTTP:
+            SET_EXPECTED_CAT_NAME(HTTP);
+        case OSSL_TRACE_CATEGORY_PROVIDER:
+            SET_EXPECTED_CAT_NAME(PROVIDER);
+        case OSSL_TRACE_CATEGORY_QUERY:
+            SET_EXPECTED_CAT_NAME(QUERY);
         default:
-            is_cat_name_eq = TEST_ptr_null(cat_name);
+            if (cat_num == -1 || cat_num >= OSSL_TRACE_CATEGORY_NUM)
+                expected_cat_name = NULL;
             break;
         }
+#undef SET_EXPECTED_CAT_NAME
 
-        if (!TEST_true(is_cat_name_eq))
+        if (!TEST_str_eq(cat_name, expected_cat_name))
             return 0;
         ret_cat_num =
             OSSL_trace_get_category_num(cat_name);
-        expected_ret = cat_name != NULL ? cat_num : -1;
+        if (cat_num < OSSL_TRACE_CATEGORY_NUM)
-        if (!TEST_int_eq(expected_ret, ret_cat_num))
+            if (!TEST_int_eq(cat_num, ret_cat_num))
-            return 0;
+                return 0;
     }
 
     return 1;