diff --git a/src/libmongoc/CMakeLists.txt b/src/libmongoc/CMakeLists.txt index dab7ce87d1d..2343df2ed02 100644 --- a/src/libmongoc/CMakeLists.txt +++ b/src/libmongoc/CMakeLists.txt @@ -1096,6 +1096,7 @@ set (test-libmongoc-sources ${PROJECT_SOURCE_DIR}/tests/test-mongoc-collection-find-with-opts.c ${PROJECT_SOURCE_DIR}/tests/test-mongoc-collection-find.c ${PROJECT_SOURCE_DIR}/tests/test-mongoc-collection.c + ${PROJECT_SOURCE_DIR}/tests/test-mongoc-command-logging-and-monitoring.c ${PROJECT_SOURCE_DIR}/tests/test-mongoc-command-monitoring.c ${PROJECT_SOURCE_DIR}/tests/test-mongoc-connection-uri.c ${PROJECT_SOURCE_DIR}/tests/test-mongoc-counters.c diff --git a/src/libmongoc/doc/mongoc_structured_log_opts_get_max_document_length.rst b/src/libmongoc/doc/mongoc_structured_log_opts_get_max_document_length.rst new file mode 100644 index 00000000000..4990a9b1842 --- /dev/null +++ b/src/libmongoc/doc/mongoc_structured_log_opts_get_max_document_length.rst @@ -0,0 +1,26 @@ +:man_page: mongoc_structured_log_opts_get_max_document_length + +mongoc_structured_log_opts_get_max_document_length() +==================================================== + +Synopsis +-------- + +.. code-block:: c + + size_t + mongoc_structured_log_opts_get_max_document_length (const mongoc_structured_log_opts_t *opts); + +Parameters +---------- + +* ``opts``: Structured log options, allocated with :symbol:`mongoc_structured_log_opts_new`. + +Returns +------- + +Returns the current maximum document length set in ``opts``, as a ``size_t``. + +.. seealso:: + + | :doc:`structured_log` diff --git a/src/libmongoc/doc/mongoc_structured_log_opts_new.rst b/src/libmongoc/doc/mongoc_structured_log_opts_new.rst index 78295e4fb94..89810b6ce3a 100644 --- a/src/libmongoc/doc/mongoc_structured_log_opts_new.rst +++ b/src/libmongoc/doc/mongoc_structured_log_opts_new.rst @@ -31,7 +31,7 @@ Environment Variables This is a full list of the captured environment variables. * ``MONGODB_LOG_MAX_DOCUMENT_LENGTH``: Maximum length for JSON-serialized documents that appear within a log message. - It may be a number, in bytes, or ``unlimited`` (case insensitive). + It may be a number, in bytes, or ``unlimited`` (case insensitive) to choose an implementation-specific value near the maximum representable length. By default, the limit is 1000 bytes. This limit affects interior documents like commands and replies, not the total length of a structured log message. diff --git a/src/libmongoc/doc/mongoc_structured_log_opts_set_max_document_length.rst b/src/libmongoc/doc/mongoc_structured_log_opts_set_max_document_length.rst new file mode 100644 index 00000000000..9c461e27b30 --- /dev/null +++ b/src/libmongoc/doc/mongoc_structured_log_opts_set_max_document_length.rst @@ -0,0 +1,33 @@ +:man_page: mongoc_structured_log_opts_set_max_document_length + +mongoc_structured_log_opts_set_max_document_length() +==================================================== + +Synopsis +-------- + +.. code-block:: c + + bool + mongoc_structured_log_opts_set_max_document_length (mongoc_structured_log_opts_t *opts, + size_t max_document_length); + +Sets a maximum length for BSON documents that appear serialized in JSON form as part of a structured log message. + +Serialized JSON will be truncated at this limit, interpreted as a count of UTF-8 encoded bytes. Truncation will be indicated with a ``...`` suffix, the length of which is not included in the max document length. If truncation at the exact indicated length would split a valid UTF-8 sequence, we instead truncate the document earlier at the nearest boundary between code points. + +Parameters +---------- + +* ``opts``: Structured log options, allocated with :symbol:`mongoc_structured_log_opts_new`. +* ``max_document_length``: Maximum length for each embedded JSON document, in bytes, not including an ellipsis (``...``) added to indicate truncation. Values near or above ``INT_MAX`` will be rejected. + +Returns +------- + +Returns ``true`` on success, or ``false`` if the supplied maximum length is too large. + +.. seealso:: + + | :doc:`structured_log` + | :symbol:`mongoc_structured_log_opts_set_max_document_length_from_env` diff --git a/src/libmongoc/doc/mongoc_structured_log_opts_set_max_document_length_from_env.rst b/src/libmongoc/doc/mongoc_structured_log_opts_set_max_document_length_from_env.rst new file mode 100644 index 00000000000..7fe2eb09da7 --- /dev/null +++ b/src/libmongoc/doc/mongoc_structured_log_opts_set_max_document_length_from_env.rst @@ -0,0 +1,34 @@ +:man_page: mongoc_structured_log_opts_set_max_document_length_from_env + +mongoc_structured_log_opts_set_max_document_length_from_env() +============================================================= + +Synopsis +-------- + +.. code-block:: c + + bool + mongoc_structured_log_opts_set_max_document_length_from_env (mongoc_structured_log_opts_t *opts); + +Sets a maximum document length from the ``MONGODB_LOG_MAX_DOCUMENT_LENGTH`` environment variable, if a valid setting is found. +See :symbol:`mongoc_structured_log_opts_new` for a description of the supported environment variable formats. + +Parse errors may cause a warning message, delivered via unstructured logging. + +This happens automatically when :symbol:`mongoc_structured_log_opts_new` establishes defaults. +Any subsequent programmatic modifications to the :symbol:`mongoc_structured_log_opts_t` will override the environment variable settings. +For applications that desire the opposite behavior, where environment variables may override programmatic settings, they may call ``mongoc_structured_log_opts_set_max_document_length_from_env()`` after calling :symbol:`mongoc_structured_log_opts_set_max_document_length`. +This will process the environment a second time, allowing it to override customized defaults. + +Returns +------- + +Returns ``true`` on success: either a valid environment setting was found, or the value is unset and ``opts`` will not be modified. +If warnings are encountered in the environment, returns ``false`` and may log additional information to the unstructured logging facility. +Note that, by design, these errors are by default non-fatal. +When :symbol:`mongoc_structured_log_opts_new` internally calls this function, it ignores the return value. + +.. seealso:: + + | :doc:`structured_log` diff --git a/src/libmongoc/doc/mongoc_structured_log_opts_t.rst b/src/libmongoc/doc/mongoc_structured_log_opts_t.rst index 414c24d804a..fbd7eb6714c 100644 --- a/src/libmongoc/doc/mongoc_structured_log_opts_t.rst +++ b/src/libmongoc/doc/mongoc_structured_log_opts_t.rst @@ -29,6 +29,9 @@ Functions mongoc_structured_log_opts_set_max_level_for_all_components mongoc_structured_log_opts_set_max_levels_from_env mongoc_structured_log_opts_get_max_level_for_component + mongoc_structured_log_opts_set_max_document_length + mongoc_structured_log_opts_set_max_document_length_from_env + mongoc_structured_log_opts_get_max_document_length .. seealso:: diff --git a/src/libmongoc/src/mongoc/mongoc-structured-log-private.h b/src/libmongoc/src/mongoc/mongoc-structured-log-private.h index 7ed1cd7fd63..4b6513da35c 100644 --- a/src/libmongoc/src/mongoc/mongoc-structured-log-private.h +++ b/src/libmongoc/src/mongoc/mongoc-structured-log-private.h @@ -34,6 +34,18 @@ typedef struct mongoc_structured_log_instance_t mongoc_structured_log_instance_t #define MONGOC_STRUCTURED_LOG_DEFAULT_LEVEL MONGOC_STRUCTURED_LOG_LEVEL_WARNING #define MONGOC_STRUCTURED_LOG_DEFAULT_MAX_DOCUMENT_LENGTH 1000 +/** + * @brief maximum possible value of the 'maximum document length' setting, enforced when reading settings from the + * environment. + * + * Maximum document length applies to a single serialized JSON document within the log. + * The overall log document, when serialized as BSON, will be subject to BSON_MAX_SIZE. + * At a minimum we should leave room for BSON headers and for the JSON truncation marker ("..."). + * Choose to leave a little more room, as it's more useful to truncate the huge document early + * rather than fail in bson_append_utf8(). + */ +#define MONGOC_STRUCTURED_LOG_MAXIMUM_MAX_DOCUMENT_LENGTH ((uint32_t) BSON_MAX_SIZE - 4096u) + /** * @brief Allocate a new instance of the structured logging system * @param opts Options, copied into the new instance. diff --git a/src/libmongoc/src/mongoc/mongoc-structured-log.c b/src/libmongoc/src/mongoc/mongoc-structured-log.c index d78f4fac655..2a25a5e8d2a 100644 --- a/src/libmongoc/src/mongoc/mongoc-structured-log.c +++ b/src/libmongoc/src/mongoc/mongoc-structured-log.c @@ -16,6 +16,8 @@ #include "common-atomic-private.h" #include "common-oid-private.h" +#include "common-string-private.h" +#include "common-json-private.h" #include "common-thread-private.h" #include "mongoc-apm-private.h" #include "mongoc-error-private.h" @@ -56,7 +58,7 @@ struct mongoc_structured_log_opts_t { mongoc_structured_log_func_t handler_func; void *handler_user_data; mongoc_structured_log_level_t max_level_per_component[STRUCTURED_LOG_COMPONENT_TABLE_SIZE]; - int32_t max_document_length; + uint32_t max_document_length; char *default_handler_path; }; @@ -190,20 +192,21 @@ _mongoc_structured_log_with_entry (const mongoc_structured_log_entry_t *entry) static bool _mongoc_structured_log_get_log_level_from_env (const char *variable, mongoc_structured_log_level_t *out, - int volatile *err_count_atomic) + int volatile *err_flag_atomic) { - const char *level = getenv (variable); + char *level = _mongoc_getenv (variable); if (!level) { return false; } - if (mongoc_structured_log_get_named_level (level, out)) { - return true; - } - // Only log the first instance of each error per process - if (0 == mcommon_atomic_int_fetch_add (err_count_atomic, 1, mcommon_memory_order_seq_cst)) { - MONGOC_WARNING ("Invalid log level '%s' read from environment variable %s. Ignoring it.", level, variable); + bool result = mongoc_structured_log_get_named_level (level, out); + if (!result) { + // Only log the first instance of each error per process + if (0 == mcommon_atomic_int_compare_exchange_strong (err_flag_atomic, 0, 1, mcommon_memory_order_seq_cst)) { + MONGOC_WARNING ("Invalid log level '%s' read from environment variable %s. Ignoring it.", level, variable); + } } - return false; + bson_free (level); + return result; } const char * @@ -269,32 +272,62 @@ mongoc_structured_log_get_named_component (const char *name, mongoc_structured_l return false; } -static int32_t -_mongoc_structured_log_get_max_document_length_from_env (void) +size_t +mongoc_structured_log_opts_get_max_document_length (const mongoc_structured_log_opts_t *opts) +{ + return (size_t) opts->max_document_length; +} + +bool +mongoc_structured_log_opts_set_max_document_length (mongoc_structured_log_opts_t *opts, size_t max_document_length) +{ + if (max_document_length <= (size_t) MONGOC_STRUCTURED_LOG_MAXIMUM_MAX_DOCUMENT_LENGTH) { + opts->max_document_length = (uint32_t) max_document_length; + return true; + } else { + return false; + } +} + +bool +mongoc_structured_log_opts_set_max_document_length_from_env (mongoc_structured_log_opts_t *opts) { + BSON_ASSERT_PARAM (opts); + const char *variable = "MONGODB_LOG_MAX_DOCUMENT_LENGTH"; - const char *max_length_str = getenv (variable); + char *max_length_str = _mongoc_getenv (variable); if (!max_length_str) { - return MONGOC_STRUCTURED_LOG_DEFAULT_MAX_DOCUMENT_LENGTH; + return true; } + bool result = false; + if (!strcasecmp (max_length_str, "unlimited")) { - return BSON_MAX_LEN_UNLIMITED; + BSON_ASSERT ( + mongoc_structured_log_opts_set_max_document_length (opts, MONGOC_STRUCTURED_LOG_MAXIMUM_MAX_DOCUMENT_LENGTH)); + result = true; + } else { + char *endptr; + long int_value = strtol (max_length_str, &endptr, 10); + if (int_value >= 0 && endptr != max_length_str && *endptr == '\0' && + mcommon_in_range_signed (size_t, int_value) && + mongoc_structured_log_opts_set_max_document_length (opts, (size_t) int_value)) { + result = true; + } } - char *endptr; - long int_value = strtol (max_length_str, &endptr, 10); - if (int_value >= 0 && int_value <= INT32_MAX && endptr != max_length_str && !*endptr) { - return (int32_t) int_value; + if (!result) { + // Only log the first instance of each error per process + static int err_flag_atomic; + if (0 == mcommon_atomic_int_compare_exchange_strong (&err_flag_atomic, 0, 1, mcommon_memory_order_seq_cst)) { + MONGOC_WARNING ( + "Invalid length '%s' read from environment variable %s. Ignoring it.", max_length_str, variable); + } } - // Only log the first instance of each error per process - static int err_count_atomic; - if (0 == mcommon_atomic_int_fetch_add (&err_count_atomic, 1, mcommon_memory_order_seq_cst)) { - MONGOC_WARNING ("Invalid length '%s' read from environment variable %s. Ignoring it.", max_length_str, variable); - } - return MONGOC_STRUCTURED_LOG_DEFAULT_MAX_DOCUMENT_LENGTH; + bson_free (max_length_str); + return result; } bool @@ -307,10 +340,10 @@ mongoc_structured_log_opts_set_max_levels_from_env (mongoc_structured_log_opts_t // Errors are not fatal by default; always reported by return value, and reported the first time only via a log // warning. - static int err_count_all_atomic; - static int err_count_per_component_atomic[STRUCTURED_LOG_COMPONENT_TABLE_SIZE]; + static int err_flag_all_atomic; + static int err_flag_per_component_atomic[STRUCTURED_LOG_COMPONENT_TABLE_SIZE]; - if (_mongoc_structured_log_get_log_level_from_env ("MONGODB_LOG_ALL", &level, &err_count_all_atomic)) { + if (_mongoc_structured_log_get_log_level_from_env ("MONGODB_LOG_ALL", &level, &err_flag_all_atomic)) { BSON_ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, level)); } else { all_ok = false; @@ -318,7 +351,7 @@ mongoc_structured_log_opts_set_max_levels_from_env (mongoc_structured_log_opts_t for (int component = 0; component < STRUCTURED_LOG_COMPONENT_TABLE_SIZE; component++) { if (_mongoc_structured_log_get_log_level_from_env ( - gStructuredLogComponentEnvVars[component], &level, &err_count_per_component_atomic[component])) { + gStructuredLogComponentEnvVars[component], &level, &err_flag_per_component_atomic[component])) { BSON_ASSERT (mongoc_structured_log_opts_set_max_level_for_component ( opts, (mongoc_structured_log_component_t) component, level)); } else { @@ -419,8 +452,9 @@ mongoc_structured_log_opts_new (void) * Note that error return values from mongoc_structured_log_opts_set_* must be ignored here. * If environment variables can't be parsed, warnings will be logged once but we must, by specification, * continue to provide structured logging using whatever valid or default settings remain. */ - opts->default_handler_path = bson_strdup (getenv ("MONGODB_LOG_PATH")); - opts->max_document_length = _mongoc_structured_log_get_max_document_length_from_env (); + opts->default_handler_path = _mongoc_getenv ("MONGODB_LOG_PATH"); + opts->max_document_length = MONGOC_STRUCTURED_LOG_DEFAULT_MAX_DOCUMENT_LENGTH; + (void) mongoc_structured_log_opts_set_max_document_length_from_env (opts); (void) mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_DEFAULT_LEVEL); (void) mongoc_structured_log_opts_set_max_levels_from_env (opts); @@ -490,15 +524,127 @@ mongoc_structured_log_instance_destroy (mongoc_structured_log_instance_t *instan } } -static char * -_mongoc_structured_log_inner_document_to_json (const bson_t *document, - size_t *length, - const mongoc_structured_log_opts_t *opts) +static mcommon_string_t * +_mongoc_structured_log_append_json_truncation_marker (mcommon_string_append_t *append) +{ + if (!mcommon_string_status_from_append (append)) { + mcommon_string_append_t marker_append; + mcommon_string_set_append (mcommon_string_from_append (append), &marker_append); + mcommon_string_append (&marker_append, "..."); + } + // Guaranteed due to choice of MONGOC_STRUCTURED_LOG_MAXIMUM_MAX_DOCUMENT_LENGTH + BSON_ASSERT (mcommon_strlen_from_append (append) <= (uint32_t) BSON_MAX_SIZE); + return mcommon_string_from_append (append); +} + +// Generic bson-to-json for documents that appear within a structured log message as truncated JSON +static mcommon_string_t * +_mongoc_structured_log_document_as_truncated_json (const bson_t *document, const mongoc_structured_log_opts_t *opts) +{ + // Use the bson_t document length as an initial buffer capacity guess + mcommon_string_append_t append; + mcommon_string_set_append_with_limit ( + mcommon_string_new_with_capacity ("", 0, document->len), &append, opts->max_document_length); + + if (mcommon_json_append_bson_document (&append, document, BSON_JSON_MODE_RELAXED, BSON_MAX_RECURSION)) { + return _mongoc_structured_log_append_json_truncation_marker (&append); + } else { + mcommon_string_from_append_destroy (&append); + return NULL; + } +} + +/** + * @brief Specialized bson-to-json conversion for mongoc_cmd_t + * @returns A new allocated mcommon_string_t, limited to the maximum document length from 'opts' plus the space for a + * possible truncation marker. Returns NULL if an invalid BSON document is encountered. This is equivalent to + * _mongoc_cmd_append_payload_as_array() combined with _mongoc_structured_log_document_as_truncated_json(), but it + * avoids ever assembling a BSON representation of the complete logged JSON document. Each payload is serialized + * separately using the mcommon_json_* functions. If we reach the maximum document length, unused portions of the input + * command will not be read. + */ +static mcommon_string_t * +_mongoc_structured_log_command_with_payloads_as_truncated_json (const mongoc_cmd_t *cmd, + const mongoc_structured_log_opts_t *opts) { - bson_json_opts_t *json_opts = bson_json_opts_new (BSON_JSON_MODE_RELAXED, opts->max_document_length); - char *json = bson_as_json_with_opts (document, length, json_opts); - bson_json_opts_destroy (json_opts); - return json; + BSON_ASSERT_PARAM (cmd); + BSON_ASSERT (!bson_empty0 (cmd->command)); + BSON_ASSERT (cmd->payloads_count <= MONGOC_CMD_PAYLOADS_COUNT_MAX); + + // Use the bson length of the command itself as an initial buffer capacity guess. + bool invalid_document = false; + mcommon_string_append_t append; + mcommon_string_set_append_with_limit ( + mcommon_string_new_with_capacity ("", 0, cmd->command->len), &append, opts->max_document_length); + + if (!mcommon_string_append (&append, "{ ")) { + goto done; + } + + if (!mcommon_json_append_bson_values ( + &append, cmd->command, BSON_JSON_MODE_RELAXED, true, BSON_MAX_RECURSION - 1u)) { + invalid_document = true; + goto done; + } + + for (size_t i = 0; i < cmd->payloads_count; i++) { + const char *field_name = cmd->payloads[i].identifier; + BSON_ASSERT (field_name); + + // Each payload is an appended key containing a non-empty sequence of documents + if (!mcommon_json_append_separator (&append) || + !mcommon_json_append_key (&append, field_name, strlen (field_name)) || + !mcommon_string_append (&append, "[ ")) { + goto done; + } + + const uint8_t *doc_begin = cmd->payloads[i].documents; + BSON_ASSERT (doc_begin); + const uint8_t *doc_end = doc_begin + cmd->payloads[i].size; + BSON_ASSERT (doc_begin != doc_end); + + const uint8_t *doc_ptr = doc_begin; + int32_t doc_len; + + while (doc_ptr + sizeof doc_len <= doc_end) { + memcpy (&doc_len, doc_ptr, sizeof doc_len); + doc_len = BSON_UINT32_FROM_LE (doc_len); + + bson_t doc; + if (doc_len < 5 || (size_t) doc_len > (size_t) (doc_end - doc_ptr) || + !bson_init_static (&doc, doc_ptr, (size_t) doc_len)) { + invalid_document = true; + goto done; + } + + if (doc_ptr != doc_begin) { + mcommon_json_append_separator (&append); + } + if (!mcommon_json_append_bson_document (&append, &doc, BSON_JSON_MODE_RELAXED, BSON_MAX_RECURSION - 2u)) { + invalid_document = true; + goto done; + } + doc_ptr += doc_len; + } + if (doc_ptr != doc_end) { + invalid_document = true; + goto done; + } + + if (!mcommon_string_append (&append, " ]")) { + goto done; + } + } + + mcommon_string_append (&append, " }"); + +done: + if (invalid_document) { + mcommon_string_from_append_destroy (&append); + return NULL; + } else { + return _mongoc_structured_log_append_json_truncation_marker (&append); + } } const mongoc_structured_log_builder_stage_t * @@ -612,12 +758,13 @@ _mongoc_structured_log_append_bson_as_json (bson_t *bson, const bson_t *bson_or_null = stage->arg2.bson; if (key_or_null) { if (bson_or_null) { - size_t json_length; - char *json = _mongoc_structured_log_inner_document_to_json (bson_or_null, &json_length, opts); + mcommon_string_t *json = _mongoc_structured_log_document_as_truncated_json (bson_or_null, opts); if (json) { - bson_append_utf8 (bson, key_or_null, -1, json, json_length); - bson_free (json); + BSON_ASSERT (json->len <= (uint32_t) INT_MAX); + bson_append_utf8 (bson, key_or_null, -1, json->str, (int) json->len); + mcommon_string_destroy (json); } + // If invalid BSON was found in the input, the key is not logged. } else { bson_append_null (bson, key_or_null, -1); } @@ -647,27 +794,14 @@ _mongoc_structured_log_append_cmd (bson_t *bson, if (mongoc_apm_is_sensitive_command_message (cmd->command_name, cmd->command)) { BSON_APPEND_UTF8 (bson, "command", "{}"); } else { - bson_t *command_copy = NULL; - - if (cmd->payloads_count > 0) { - // @todo This is a performance bottleneck, we shouldn't be copying - // a potentially large command to serialize a potentially very - // small part of it. We should be appending JSON to a single buffer - // for all nesting levels, constrained by length limit, while visiting - // borrowed references to each command attribute and each payload. CDRIVER-4814 - command_copy = bson_copy (cmd->command); - _mongoc_cmd_append_payload_as_array (cmd, command_copy); - } - - size_t json_length; - char *json = _mongoc_structured_log_inner_document_to_json ( - command_copy ? command_copy : cmd->command, &json_length, opts); + mcommon_string_t *json = _mongoc_structured_log_command_with_payloads_as_truncated_json (cmd, opts); if (json) { const char *key = "command"; - bson_append_utf8 (bson, key, strlen (key), json, json_length); - bson_free (json); + BSON_ASSERT (json->len <= (uint32_t) INT_MAX); + bson_append_utf8 (bson, key, strlen (key), json->str, (int) json->len); + mcommon_string_destroy (json); } - bson_destroy (command_copy); + // If invalid BSON was found in the input, the key is not logged. } } @@ -683,13 +817,14 @@ _mongoc_structured_log_append_redacted_cmd_reply (bson_t *bson, if (is_sensitive) { BSON_APPEND_UTF8 (bson, "reply", "{}"); } else { - size_t json_length; - char *json = _mongoc_structured_log_inner_document_to_json (reply, &json_length, opts); + mcommon_string_t *json = _mongoc_structured_log_document_as_truncated_json (reply, opts); if (json) { const char *key = "reply"; - bson_append_utf8 (bson, key, strlen (key), json, json_length); - bson_free (json); + BSON_ASSERT (json->len <= (uint32_t) INT_MAX); + bson_append_utf8 (bson, key, strlen (key), json->str, (int) json->len); + mcommon_string_destroy (json); } + // If invalid BSON was found in the input, the key is not logged. } } @@ -897,18 +1032,13 @@ _mongoc_structured_log_append_topology_as_description_json (bson_t *bson, mc_shared_tpld td = mc_tpld_take_ref (topology_or_null); bson_t inner_bson = BSON_INITIALIZER; mongoc_topology_description_append_contents_to_bson (td.ptr, &inner_bson, td_flags, server_flags); - size_t json_length; - char *json = _mongoc_structured_log_inner_document_to_json (&inner_bson, &json_length, opts); - /* TODO: This will be replaced shortly with a spec compliant string truncation implementation. - * Note the INT_MAX size limit specific to bson_append_utf8(), vs the UINT32_MAX-1 internal limits. - * This check will move as part of centralizing truncation behavior, with the benefits of - * preserving UTF-8 sequence integrity and consistently inserting "..." when truncating. - */ + mcommon_string_t *json = _mongoc_structured_log_document_as_truncated_json (&inner_bson, opts); if (json) { - bson_append_utf8 ( - bson, key_or_null, -1, json, json_length > (size_t) INT_MAX ? INT_MAX : (int) json_length); - bson_free (json); + BSON_ASSERT (json->len <= (uint32_t) INT_MAX); + bson_append_utf8 (bson, key_or_null, -1, json->str, (int) json->len); + mcommon_string_destroy (json); } + // If invalid BSON was found in the input, the key is not logged. bson_destroy (&inner_bson); mc_tpld_drop_ref (&td); } else { diff --git a/src/libmongoc/src/mongoc/mongoc-structured-log.h b/src/libmongoc/src/mongoc/mongoc-structured-log.h index 468e408d415..5bddc36ba24 100644 --- a/src/libmongoc/src/mongoc/mongoc-structured-log.h +++ b/src/libmongoc/src/mongoc/mongoc-structured-log.h @@ -77,6 +77,15 @@ MONGOC_EXPORT (mongoc_structured_log_level_t) mongoc_structured_log_opts_get_max_level_for_component (const mongoc_structured_log_opts_t *opts, mongoc_structured_log_component_t component); +MONGOC_EXPORT (size_t) +mongoc_structured_log_opts_get_max_document_length (const mongoc_structured_log_opts_t *opts); + +MONGOC_EXPORT (bool) +mongoc_structured_log_opts_set_max_document_length_from_env (mongoc_structured_log_opts_t *opts); + +MONGOC_EXPORT (bool) +mongoc_structured_log_opts_set_max_document_length (mongoc_structured_log_opts_t *opts, size_t max_document_length); + MONGOC_EXPORT (bson_t *) mongoc_structured_log_entry_message_as_bson (const mongoc_structured_log_entry_t *entry); diff --git a/src/libmongoc/tests/test-libmongoc-main.c b/src/libmongoc/tests/test-libmongoc-main.c index 20b25c40cfa..18fa2b820ee 100644 --- a/src/libmongoc/tests/test-libmongoc-main.c +++ b/src/libmongoc/tests/test-libmongoc-main.c @@ -70,6 +70,7 @@ main (int argc, char *argv[]) TEST_INSTALL (test_collection_find_install); TEST_INSTALL (test_collection_find_with_opts_install); TEST_INSTALL (test_connection_uri_install); + TEST_INSTALL (test_command_logging_and_monitoring_install); TEST_INSTALL (test_command_monitoring_install); TEST_INSTALL (test_cursor_install); TEST_INSTALL (test_database_install); diff --git a/src/libmongoc/tests/test-mongoc-command-logging-and-monitoring.c b/src/libmongoc/tests/test-mongoc-command-logging-and-monitoring.c new file mode 100644 index 00000000000..6121728b837 --- /dev/null +++ b/src/libmongoc/tests/test-mongoc-command-logging-and-monitoring.c @@ -0,0 +1,358 @@ +#include + +#include "test-libmongoc.h" +#include "test-conveniences.h" +#include "mongoc/mongoc-array-private.h" +#include "TestSuite.h" + +static void +stored_log_handler (const mongoc_structured_log_entry_t *entry, void *user_data) +{ + mongoc_array_t *log_array = (mongoc_array_t *) user_data; + bson_t *doc = mongoc_structured_log_entry_message_as_bson (entry); + MONGOC_DEBUG ("stored log: %s", tmp_json (doc)); + _mongoc_array_append_val (log_array, doc); +} + +static void +stored_log_clear (mongoc_array_t *log_array) +{ + for (size_t i = 0; i < log_array->len; i++) { + bson_t *doc = _mongoc_array_index (log_array, bson_t *, i); + bson_destroy (doc); + } + _mongoc_array_clear (log_array); +} + +/* specifications/source/command-logging-and-monitoring/tests/README.md + * Test 1: Default truncation limit */ +static void +prose_test_1 (void) +{ + // 1. Configure logging with a minimum severity level of "debug" for the "command" component. Do not explicitly + // configure the max document length. + mongoc_client_t *client = test_framework_new_default_client (); + mongoc_array_t stored_log; + _mongoc_array_init (&stored_log, sizeof (bson_t *)); + { + mongoc_structured_log_opts_t *log_opts = mongoc_structured_log_opts_new (); + + ASSERT (mongoc_structured_log_opts_set_max_level_for_component ( + log_opts, MONGOC_STRUCTURED_LOG_COMPONENT_COMMAND, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); + + mongoc_structured_log_opts_set_handler (log_opts, stored_log_handler, &stored_log); + + ASSERT (mongoc_client_set_structured_log_opts (client, log_opts)); + mongoc_structured_log_opts_destroy (log_opts); + } + mongoc_collection_t *coll = mongoc_client_get_collection (client, "db", "coll"); + + // 2. Construct an array docs containing the document {"x" : "y"} repeated 100 times. + bson_t *docs[100]; + for (unsigned i = 0; i < sizeof docs / sizeof docs[0]; i++) { + docs[i] = tmp_bson (BSON_STR ({"x" : "y"})); + } + + // 3. Insert docs to a collection via insertMany. + bson_error_t error; + ASSERT_OR_PRINT ( + mongoc_collection_insert_many (coll, (const bson_t **) docs, sizeof docs / sizeof docs[0], NULL, NULL, &error), + error); + + // 4. Inspect the resulting "command started" log message and assert that the "command" value is a string of length + // 1000 + (length of trailing ellipsis). + { + ASSERT (stored_log.len >= 1); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 0); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command started"); + ASSERT (bson_iter_find (&iter, "command")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + uint32_t command_len; + const char *command = bson_iter_utf8 (&iter, &command_len); + ASSERT (command); + ASSERT_CMPUINT32 (command_len, ==, 1003); + } + + // 5. Inspect the resulting "command succeeded" log message and assert that the "reply" value is a string of length + // <= 1000 + (length of trailing ellipsis). + { + ASSERT (stored_log.len == 2); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 1); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command succeeded"); + ASSERT (bson_iter_find (&iter, "reply")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + uint32_t reply_len; + const char *reply = bson_iter_utf8 (&iter, &reply_len); + ASSERT (reply); + ASSERT_CMPUINT32 (reply_len, <=, 1003); + } + + // 6. Run find() on the collection where the document was inserted. + stored_log_clear (&stored_log); + mongoc_cursor_t *cursor = mongoc_collection_find_with_opts (coll, tmp_bson ("{}"), NULL, NULL); + ASSERT (cursor); + { + const bson_t *doc; + ASSERT (mongoc_cursor_next (cursor, &doc)); + } + + // 7. Inspect the resulting "command succeeded" log message and assert that the reply is a string of length 1000 + + // (length of trailing ellipsis). + { + ASSERT (stored_log.len >= 1); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 0); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command started"); + } + { + ASSERT (stored_log.len == 2); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 1); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command succeeded"); + ASSERT (bson_iter_find (&iter, "reply")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + uint32_t reply_len; + const char *reply = bson_iter_utf8 (&iter, &reply_len); + ASSERT (reply); + ASSERT_CMPUINT32 (reply_len, ==, 1003); + } + + mongoc_cursor_destroy (cursor); + mongoc_collection_destroy (coll); + mongoc_client_destroy (client); + stored_log_clear (&stored_log); + _mongoc_array_destroy (&stored_log); +} + +/* Test 2: Explicitly configured truncation limit */ +static void +prose_test_2 (void) +{ + // 1. Configure logging with a minimum severity level of "debug" for the "command" component. Set the max document + // length to 5. + mongoc_client_t *client = test_framework_new_default_client (); + mongoc_array_t stored_log; + _mongoc_array_init (&stored_log, sizeof (bson_t *)); + { + mongoc_structured_log_opts_t *log_opts = mongoc_structured_log_opts_new (); + + ASSERT (mongoc_structured_log_opts_set_max_document_length (log_opts, 5)); + ASSERT (mongoc_structured_log_opts_set_max_level_for_component ( + log_opts, MONGOC_STRUCTURED_LOG_COMPONENT_COMMAND, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); + + mongoc_structured_log_opts_set_handler (log_opts, stored_log_handler, &stored_log); + + ASSERT (mongoc_client_set_structured_log_opts (client, log_opts)); + mongoc_structured_log_opts_destroy (log_opts); + } + + // 2. Run the command {"hello": true}. + { + bson_error_t error; + ASSERT_OR_PRINT ( + mongoc_client_command_simple (client, "db", tmp_bson (BSON_STR ({"hello" : true})), NULL, NULL, &error), + error); + } + + // 3. Inspect the resulting "command started" log message and assert that the "command" value is a string of length 5 + // + (length of trailing ellipsis). + { + ASSERT (stored_log.len >= 1); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 0); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command started"); + ASSERT (bson_iter_find (&iter, "command")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + uint32_t command_len; + const char *command = bson_iter_utf8 (&iter, &command_len); + ASSERT (command); + ASSERT_CMPUINT32 (command_len, ==, 5 + 3); + ASSERT_CMPSTR (command, "{ \"he..."); + } + + // 4. Inspect the resulting "command succeeded" log message and assert that the "reply" value is a string of length 5 + // + (length of trailing ellipsis). + { + ASSERT (stored_log.len == 2); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 1); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command succeeded"); + ASSERT (bson_iter_find (&iter, "reply")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + uint32_t reply_len; + const char *reply = bson_iter_utf8 (&iter, &reply_len); + ASSERT (reply); + ASSERT_CMPUINT32 (reply_len, ==, 5 + 3); + } + + // 5. If the driver attaches raw server responses to failures and can access these via log messages to assert on, run + // the command {"notARealCommand": true}. Inspect the resulting "command failed" log message and confirm that the + // server error is a string of length 5 + (length of trailing ellipsis). + // + // This is not applicable to libmongoc. The spec allows flexible data type for "failure", and here we chose a + // document rather than a string. The document is not subject to truncation. + // + // While we're here, test that the proposed fake command itself is truncated as expected, and the "failure" is a + // document. + stored_log_clear (&stored_log); + ASSERT ( + !mongoc_client_command_simple (client, "db", tmp_bson (BSON_STR ({"notARealCommand" : true})), NULL, NULL, NULL)); + { + ASSERT (stored_log.len >= 1); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 0); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command started"); + ASSERT (bson_iter_find (&iter, "command")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + uint32_t command_len; + const char *command = bson_iter_utf8 (&iter, &command_len); + ASSERT (command); + ASSERT_CMPUINT32 (command_len, ==, 5 + 3); + ASSERT_CMPSTR (command, "{ \"no..."); + } + { + ASSERT (stored_log.len == 2); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 1); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command failed"); + ASSERT (bson_iter_find (&iter, "failure")); + ASSERT (BSON_ITER_HOLDS_DOCUMENT (&iter)); + } + + mongoc_client_destroy (client); + stored_log_clear (&stored_log); + _mongoc_array_destroy (&stored_log); +} + +/* Test 3: Truncation with multi-byte code points */ +static void +prose_test_3 (void) +{ + // "Drivers MUST write language-specific tests that confirm truncation of commands, replies, and (if applicable) + // server responses included in error messages work as expected when the data being truncated includes multi-byte + // Unicode codepoints." "If the driver uses anything other than Unicode codepoints as the unit for max document + // length, there also MUST be tests confirming that cases where the max length falls in the middle of a multi-byte + // codepoint are handled gracefully." + // + // For libmongoc, our max length is in bytes and truncation will round lengths down if necessary to avoid splitting a + // valid UTF-8 sequence. This test repeatedly sends a fake command to the server using every possible maximum + // length, checking for the expected truncations. + + bson_t command = BSON_INITIALIZER; + BSON_APPEND_BOOL (&command, "notARealCommand", true); + BSON_APPEND_UTF8 (&command, "twoByteUtf8", "\xc2\xa9"); + BSON_APPEND_UTF8 (&command, "threeByteUtf8", "\xef\xbf\xbd"); + BSON_APPEND_UTF8 (&command, "fourByteUtf8", "\xf4\x8f\xbf\xbf"); + + // Stop testing after $db, before we reach lsid. The result will always be truncated. + const char *expected_json = "{ \"notARealCommand\" : true, \"twoByteUtf8\" : \"\xc2\xa9\", \"threeByteUtf8\" : " + "\"\xef\xbf\xbd\", \"fourByteUtf8\" : \"\xf4\x8f\xbf\xbf\", \"$db\" : \"db\""; + const int max_expected_length = strlen (expected_json); + + // List of lengths we expect not to see when trying every max_expected_length + static const int expect_missing_lengths[] = {46, 70, 71, 94, 95, 96}; + + mongoc_client_t *client = test_framework_new_default_client (); + + int expected_length = 0; + for (int test_length = 0; test_length <= max_expected_length; test_length++) { + MONGOC_DEBUG ("testing length %d of %d", test_length, max_expected_length); + + // Track the expected length of a serialized string with the max_document_length set to 'test_length'. + // When a length is mentioned in expect_missing_lengths, we let the expected_length lag behind the test_length. + // At this point, the ellipsis length is not included. + bool expect_missing = false; + if (test_length > max_expected_length) { + expect_missing = true; + } else { + for (int missing = 0; missing < sizeof expect_missing_lengths / sizeof expect_missing_lengths[0]; missing++) { + if (expect_missing_lengths[missing] == test_length) { + expect_missing = true; + break; + } + } + } + if (!expect_missing) { + expected_length = test_length; + } + + // Set up the log options for each command, to test this new max_document_length + mongoc_structured_log_opts_t *log_opts = mongoc_structured_log_opts_new (); + ASSERT (mongoc_structured_log_opts_set_max_document_length (log_opts, test_length)); + ASSERT (mongoc_structured_log_opts_set_max_level_for_component ( + log_opts, MONGOC_STRUCTURED_LOG_COMPONENT_COMMAND, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); + + mongoc_array_t stored_log; + _mongoc_array_init (&stored_log, sizeof (bson_t *)); + mongoc_structured_log_opts_set_handler (log_opts, stored_log_handler, &stored_log); + ASSERT (mongoc_client_set_structured_log_opts (client, log_opts)); + mongoc_structured_log_opts_destroy (log_opts); + + ASSERT (!mongoc_client_command_simple (client, "db", &command, NULL, NULL, NULL)); + + ASSERT (stored_log.len >= 1); + bson_t *log = _mongoc_array_index (&stored_log, bson_t *, 0); + bson_iter_t iter; + ASSERT (bson_iter_init (&iter, log)); + ASSERT (bson_iter_find (&iter, "message")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + ASSERT_CMPSTR (bson_iter_utf8 (&iter, NULL), "Command started"); + ASSERT (bson_iter_find (&iter, "command")); + ASSERT (BSON_ITER_HOLDS_UTF8 (&iter)); + uint32_t logged_command_len; + const char *logged_command_str = bson_iter_utf8 (&iter, &logged_command_len); + ASSERT (logged_command_str); + ASSERT_CMPUINT32 (logged_command_len, ==, expected_length + 3); + + // Note that here we do not use mcommon_string to truncate, just as a convenient way to represent the + // expected string with ellipsis for ASSERT_CMPSTR. (The code under test internally uses mcommon_string_append_t + // also.) + mcommon_string_append_t expected_json_truncated; + mcommon_string_new_as_append (&expected_json_truncated); + mcommon_string_append_bytes (&expected_json_truncated, expected_json, expected_length); + mcommon_string_append (&expected_json_truncated, "..."); + ASSERT_CMPSTR (logged_command_str, mcommon_str_from_append (&expected_json_truncated)); + mcommon_string_from_append_destroy (&expected_json_truncated); + + ASSERT (mongoc_client_set_structured_log_opts (client, NULL)); + stored_log_clear (&stored_log); + _mongoc_array_destroy (&stored_log); + } + + mongoc_client_destroy (client); + bson_destroy (&command); +} + +void +test_command_logging_and_monitoring_install (TestSuite *suite) +{ + TestSuite_AddLive (suite, "/command-logging-and-monitoring/logging/prose_test_1", prose_test_1); + TestSuite_AddLive (suite, "/command-logging-and-monitoring/logging/prose_test_2", prose_test_2); + TestSuite_AddLive (suite, "/command-logging-and-monitoring/logging/prose_test_3", prose_test_3); +} diff --git a/src/libmongoc/tests/test-mongoc-structured-log.c b/src/libmongoc/tests/test-mongoc-structured-log.c index fa32b1d35c6..9243a02d7f2 100644 --- a/src/libmongoc/tests/test-mongoc-structured-log.c +++ b/src/libmongoc/tests/test-mongoc-structured-log.c @@ -17,6 +17,7 @@ #include #include "mongoc/mongoc-structured-log-private.h" +#include "test-libmongoc.h" #include "TestSuite.h" typedef struct log_assumption { @@ -65,6 +66,7 @@ test_structured_log_opts (void) { mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); + ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_WARNING)); ASSERT_CMPINT ( MONGOC_STRUCTURED_LOG_LEVEL_WARNING, ==, @@ -88,7 +90,6 @@ test_structured_log_opts (void) ASSERT (!mongoc_structured_log_opts_set_max_level_for_all_components (opts, (mongoc_structured_log_level_t) -1)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_INFO)); - ASSERT_CMPINT ( MONGOC_STRUCTURED_LOG_LEVEL_INFO, ==, @@ -142,6 +143,12 @@ test_structured_log_plain (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + + /* Note about these max_document_length settings: We want a consistent value so the test is isolated from external + * environment variable settings. The default (MONGOC_STRUCTURED_LOG_DEFAULT_MAX_DOCUMENT_LENGTH) is verified as 1000 + * bytes elsewhere. The Command Logging and Monitoring spec recommends that tests run with a larger-than-default + * setting of 10000 bytes. We choose that value here, but it's really quite arbitrary. */ + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -168,6 +175,7 @@ test_structured_log_plain_with_extra_data (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -222,6 +230,7 @@ test_structured_log_basic_data_types (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -274,6 +283,7 @@ test_structured_log_json (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -314,6 +324,7 @@ test_structured_log_oid (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -363,6 +374,7 @@ test_structured_log_error (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_INFO)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -435,6 +447,7 @@ test_structured_log_server_description (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -466,52 +479,56 @@ test_structured_log_command (void) .expected_envelope.level = MONGOC_STRUCTURED_LOG_LEVEL_WARNING, .expected_envelope.component = MONGOC_STRUCTURED_LOG_COMPONENT_COMMAND, .expected_envelope.message = "Log entry with command and reply fields", - .expected_bson = BCON_NEW ("message", - BCON_UTF8 ("Log entry with command and reply fields"), - "commandName", - BCON_UTF8 ("Not a command"), - "databaseName", - BCON_UTF8 ("Some database"), - "commandName", - BCON_UTF8 ("Not a command"), - "operationId", - BCON_INT64 (0x12345678eeff0011), - "command", - BCON_UTF8 ("{ \"c\" : \"d\" }"), - "reply", // Un-redacted successful reply (not-a-command) - BCON_UTF8 ("{ \"r\" : \"s\", \"code\" : 1 }"), - "reply", // Un-redacted successful reply (ping) - BCON_UTF8 ("{ \"r\" : \"s\", \"code\" : 1 }"), - "reply", // Redacted successful reply (auth) - BCON_UTF8 ("{}"), - "failure", // Un-redacted server side error (not-a-command) - "{", - "r", - BCON_UTF8 ("s"), - "code", - BCON_INT32 (1), - "}", - "failure", // Un-redacted server side error (ping) - "{", - "r", - BCON_UTF8 ("s"), - "code", - BCON_INT32 (1), - "}", - "failure", // Redacted server side error (auth) - "{", - "code", - BCON_INT32 (1), - "}", - "failure", // Client side error - "{", - "code", - BCON_INT32 (123), - "domain", - BCON_INT32 (456), - "message", - BCON_UTF8 ("oh no"), - "}"), + .expected_bson = + BCON_NEW ("message", + BCON_UTF8 ("Log entry with command and reply fields"), + "commandName", + BCON_UTF8 ("Not a command"), + "databaseName", + BCON_UTF8 ("Some database"), + "commandName", + BCON_UTF8 ("Not a command"), + "operationId", + BCON_INT64 (0x12345678eeff0011), + "command", + BCON_UTF8 ("{ \"c\" : \"d\", \"first_payload\" : [ { \"i\" : 0, \"x\" : 0 }, { \"i\" : 0, \"x\" : 1 " + "}, { \"i\" : 0, \"x\" : 2 }, { \"i\" : 0, \"x\" : 3 }, { \"i\" : 0, \"x\" : 4 } ], " + "\"second_payload\" : [ { \"i\" : 1, \"x\" : 0 }, { \"i\" : 1, \"x\" : 1 }, { \"i\" : 1, " + "\"x\" : 2 }, { \"i\" : 1, \"x\" : 3 }, { \"i\" : 1, \"x\" : 4 } ] }"), + "reply", // Un-redacted successful reply (not-a-command) + BCON_UTF8 ("{ \"r\" : \"s\", \"code\" : 1 }"), + "reply", // Un-redacted successful reply (ping) + BCON_UTF8 ("{ \"r\" : \"s\", \"code\" : 1 }"), + "reply", // Redacted successful reply (auth) + BCON_UTF8 ("{}"), + "failure", // Un-redacted server side error (not-a-command) + "{", + "r", + BCON_UTF8 ("s"), + "code", + BCON_INT32 (1), + "}", + "failure", // Un-redacted server side error (ping) + "{", + "r", + BCON_UTF8 ("s"), + "code", + BCON_INT32 (1), + "}", + "failure", // Redacted server side error (auth) + "{", + "code", + BCON_INT32 (1), + "}", + "failure", // Client side error + "{", + "code", + BCON_INT32 (123), + "domain", + BCON_INT32 (456), + "message", + BCON_UTF8 ("oh no"), + "}"), .expected_calls = 1, }; @@ -529,15 +546,47 @@ test_structured_log_command (void) .message = "oh no", }; + // Current value of MONGOC_CMD_PAYLOADS_COUNT_MAX is 2. + // Write two payloads, each with multiple documents in sequence. + uint8_t *payload_buf[2] = {NULL, NULL}; + size_t payload_buflen[2] = {0, 0}; + bson_writer_t *payload_writer[2] = { + bson_writer_new (&payload_buf[0], &payload_buflen[0], 0, bson_realloc_ctx, NULL), + bson_writer_new (&payload_buf[1], &payload_buflen[1], 0, bson_realloc_ctx, NULL), + }; + for (unsigned x = 0; x < 5; x++) { + for (unsigned i = 0; i < sizeof payload_writer / sizeof payload_writer[0]; i++) { + bson_t *doc; + bson_writer_begin (payload_writer[i], &doc); + BCON_APPEND (doc, "i", BCON_INT32 (i), "x", BCON_INT32 (x)); + bson_writer_end (payload_writer[i]); + } + } + mongoc_cmd_t cmd = { .db_name = "Some database", .command_name = "Not a command", .operation_id = 0x12345678eeff0011, .command = cmd_doc, + .payloads = + { + {.identifier = "first_payload", + .documents = payload_buf[0], + .size = bson_writer_get_length (payload_writer[0])}, + {.identifier = "second_payload", + .documents = payload_buf[1], + .size = bson_writer_get_length (payload_writer[0])}, + }, + .payloads_count = 2, }; + for (unsigned i = 0; i < sizeof payload_writer / sizeof payload_writer[0]; i++) { + bson_writer_destroy (payload_writer[i]); + } + mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -562,6 +611,9 @@ test_structured_log_command (void) bson_destroy (assumption.expected_bson); bson_destroy (cmd_doc); bson_destroy (reply_doc); + for (unsigned i = 0; i < sizeof payload_buf / sizeof payload_buf[0]; i++) { + bson_free (payload_buf[i]); + } } void @@ -590,6 +642,7 @@ test_structured_log_duration (void) mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); mongoc_structured_log_opts_set_handler (opts, structured_log_func, &assumption); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 10000)); ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components (opts, MONGOC_STRUCTURED_LOG_LEVEL_DEBUG)); mongoc_structured_log_instance_t *instance = mongoc_structured_log_instance_new (opts); @@ -699,6 +752,76 @@ test_structured_log_component_names (void) ASSERT_CMPSTR (mongoc_structured_log_get_component_name (component), "connection"); } +void +test_structured_log_max_document_length (void) +{ + mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); + + ASSERT_CMPINT (MONGOC_STRUCTURED_LOG_DEFAULT_MAX_DOCUMENT_LENGTH, ==, 1000); + + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, 0)); + ASSERT (!mongoc_structured_log_opts_set_max_document_length (opts, INT_MAX)); + ASSERT (mongoc_structured_log_opts_set_max_document_length (opts, INT_MAX / 2)); + ASSERT_CMPINT (INT_MAX / 2, ==, mongoc_structured_log_opts_get_max_document_length (opts)); + + mongoc_structured_log_opts_destroy (opts); +} + +int +test_structured_log_skip_if_env_not_default (void) +{ + // Skip testing env defaults if any options have been set externally + const char *expected_unset[] = { + "MONGODB_LOG_MAX_DOCUMENT_LENGTH", + "MONGODB_LOG_COMMAND", + "MONGODB_LOG_TOPOLOGY", + "MONGODB_LOG_SERVER_SELECTION", + "MONGODB_LOG_CONNECTION", + "MONGODB_LOG_ALL", + }; + + for (size_t i = 0u; i < sizeof expected_unset / sizeof expected_unset[0]; i++) { + const char *var = expected_unset[i]; + char *value = test_framework_getenv (var); + bson_free (value); + if (value) { + MONGOC_DEBUG ("Skipping test because environment var '%s' is set", var); + return 0; + } + } + return 1; +} + +void +test_structured_log_env_defaults (void *test_context) +{ + BSON_UNUSED (test_context); + + mongoc_structured_log_opts_t *opts = mongoc_structured_log_opts_new (); + + ASSERT_CMPINT ( + MONGOC_STRUCTURED_LOG_LEVEL_WARNING, + ==, + mongoc_structured_log_opts_get_max_level_for_component (opts, MONGOC_STRUCTURED_LOG_COMPONENT_COMMAND)); + ASSERT_CMPINT ( + MONGOC_STRUCTURED_LOG_LEVEL_WARNING, + ==, + mongoc_structured_log_opts_get_max_level_for_component (opts, MONGOC_STRUCTURED_LOG_COMPONENT_CONNECTION)); + ASSERT_CMPINT ( + MONGOC_STRUCTURED_LOG_LEVEL_WARNING, + ==, + mongoc_structured_log_opts_get_max_level_for_component (opts, MONGOC_STRUCTURED_LOG_COMPONENT_SERVER_SELECTION)); + ASSERT_CMPINT ( + MONGOC_STRUCTURED_LOG_LEVEL_WARNING, + ==, + mongoc_structured_log_opts_get_max_level_for_component (opts, MONGOC_STRUCTURED_LOG_COMPONENT_TOPOLOGY)); + + ASSERT_CMPINT ( + MONGOC_STRUCTURED_LOG_DEFAULT_MAX_DOCUMENT_LENGTH, ==, mongoc_structured_log_opts_get_max_document_length (opts)); + + mongoc_structured_log_opts_destroy (opts); +} + void test_structured_log_install (TestSuite *suite) { @@ -714,4 +837,11 @@ test_structured_log_install (TestSuite *suite) TestSuite_Add (suite, "/structured_log/duration", test_structured_log_duration); TestSuite_Add (suite, "/structured_log/level_names", test_structured_log_level_names); TestSuite_Add (suite, "/structured_log/component_names", test_structured_log_component_names); + TestSuite_Add (suite, "/structured_log/max_document_length", test_structured_log_max_document_length); + TestSuite_AddFull (suite, + "/structured_log/env_defaults", + test_structured_log_env_defaults, + NULL, + NULL, + test_structured_log_skip_if_env_not_default); } diff --git a/src/libmongoc/tests/unified/entity-map.c b/src/libmongoc/tests/unified/entity-map.c index 9b7d68a84bb..7ce5feb4e12 100644 --- a/src/libmongoc/tests/unified/entity-map.c +++ b/src/libmongoc/tests/unified/entity-map.c @@ -638,6 +638,9 @@ entity_client_new (entity_map_t *em, bson_t *bson, bson_error_t *error) BSON_ASSERT (mongoc_structured_log_opts_set_max_level_for_all_components ( log_opts, MONGOC_STRUCTURED_LOG_LEVEL_EMERGENCY)); mongoc_structured_log_opts_set_handler (log_opts, structured_log_cb, entity); + // From the Command Logging and Monitoring / Testing spec, unified tests MUST be run with their max + // document length set to "a large value e.g. 10,000". Note that the default setting is 1000. + mongoc_structured_log_opts_set_max_document_length (log_opts, 10000); }), visitEach ( if (not(type (utf8)), then (error ("Every value in 'observeLogMessages' must be a log level string"))),