From c7ece1d22dba4a574c80ce063bee73e1ad2e3a48 Mon Sep 17 00:00:00 2001 From: Etienne Petrel Date: Thu, 18 Nov 2021 14:43:44 +0000 Subject: Import wiredtiger: 9bc9737c2474d6dc4bed669f859195a9fd898ae6 from branch mongodb-master ref: 90a99d5f2d..9bc9737c24 for: 5.2.0 WT-8258 Implement JSON encoded strings to be produced by the WT_EVENT_HANDLER API --- src/third_party/wiredtiger/dist/api_data.py | 7 + src/third_party/wiredtiger/import.data | 2 +- src/third_party/wiredtiger/src/config/config_def.c | 61 +++--- src/third_party/wiredtiger/src/conn/conn_api.c | 14 ++ .../wiredtiger/src/include/connection.h | 6 + .../wiredtiger/src/include/wiredtiger.in | 8 + src/third_party/wiredtiger/src/support/err.c | 224 ++++++++++++++++----- .../wiredtiger/test/suite/test_verbose01.py | 38 +++- .../wiredtiger/test/suite/test_verbose02.py | 18 +- 9 files changed, 282 insertions(+), 96 deletions(-) diff --git a/src/third_party/wiredtiger/dist/api_data.py b/src/third_party/wiredtiger/dist/api_data.py index 499738b745c..247b3aa6868 100644 --- a/src/third_party/wiredtiger/dist/api_data.py +++ b/src/third_party/wiredtiger/dist/api_data.py @@ -748,6 +748,13 @@ connection_runtime_config = [ is 1MB.''', min='0', max='1TB'), ]), + Config('json_output', '[]', r''' + enable JSON formatted messages on the event handler interface. Options are + given as a list, where each option specifies an event handler category e.g. + 'error' represents the messages from the WT_EVENT_HANDLER::handle_error method.''', + type='list', choices=[ + 'error', + 'message']), Config('lsm_manager', '', r''' configure database wide options for LSM tree management. The LSM manager is started automatically the first time an LSM tree is opened. diff --git a/src/third_party/wiredtiger/import.data b/src/third_party/wiredtiger/import.data index 75061339762..02338cfecd4 100644 --- a/src/third_party/wiredtiger/import.data +++ b/src/third_party/wiredtiger/import.data @@ -2,5 +2,5 @@ "vendor": "wiredtiger", "github": "wiredtiger/wiredtiger.git", "branch": "mongodb-master", - "commit": "90a99d5f2dc1a8490aebe000ecf388d48ce1ed61" + "commit": "9bc9737c2474d6dc4bed669f859195a9fd898ae6" } diff --git a/src/third_party/wiredtiger/src/config/config_def.c b/src/third_party/wiredtiger/src/config/config_def.c index 331142d3274..c8022b36fec 100644 --- a/src/third_party/wiredtiger/src/config/config_def.c +++ b/src/third_party/wiredtiger/src/config/config_def.c @@ -140,6 +140,7 @@ static const WT_CONFIG_CHECK confchk_WT_CONNECTION_reconfigure[] = { {"file_manager", "category", NULL, NULL, confchk_wiredtiger_open_file_manager_subconfigs, 3}, {"history_store", "category", NULL, NULL, confchk_wiredtiger_open_history_store_subconfigs, 1}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, + {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, {"log", "category", NULL, NULL, confchk_WT_CONNECTION_reconfigure_log_subconfigs, 4}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"operation_timeout_ms", "int", NULL, "min=1", NULL, 0}, @@ -871,6 +872,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open[] = { {"history_store", "category", NULL, NULL, confchk_wiredtiger_open_history_store_subconfigs, 1}, {"in_memory", "boolean", NULL, NULL, NULL, 0}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, + {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 9}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, @@ -954,6 +956,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_all[] = { {"history_store", "category", NULL, NULL, confchk_wiredtiger_open_history_store_subconfigs, 1}, {"in_memory", "boolean", NULL, NULL, NULL, 0}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, + {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 9}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, @@ -1034,6 +1037,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_basecfg[] = { {"hazard_max", "int", NULL, "min=15", NULL, 0}, {"history_store", "category", NULL, NULL, confchk_wiredtiger_open_history_store_subconfigs, 1}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, + {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 9}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, @@ -1112,6 +1116,7 @@ static const WT_CONFIG_CHECK confchk_wiredtiger_open_usercfg[] = { {"hazard_max", "int", NULL, "min=15", NULL, 0}, {"history_store", "category", NULL, NULL, confchk_wiredtiger_open_history_store_subconfigs, 1}, {"io_capacity", "category", NULL, NULL, confchk_wiredtiger_open_io_capacity_subconfigs, 1}, + {"json_output", "list", NULL, "choices=[\"error\",\"message\"]", NULL, 0}, {"log", "category", NULL, NULL, confchk_wiredtiger_open_log_subconfigs, 9}, {"lsm_manager", "category", NULL, NULL, confchk_wiredtiger_open_lsm_manager_subconfigs, 2}, {"mmap", "boolean", NULL, NULL, NULL, 0}, {"mmap_all", "boolean", NULL, NULL, NULL, 0}, @@ -1196,17 +1201,17 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", ",eviction_updates_target=0,eviction_updates_trigger=0," "file_manager=(close_handle_minimum=250,close_idle_time=30," "close_scan_interval=10),history_store=(file_max=0)," - "io_capacity=(total=0),log=(archive=true,os_cache_dirty_pct=0," - "prealloc=true,zero_fill=false),lsm_manager=(merge=true," - "worker_thread_max=4),operation_timeout_ms=0," - "operation_tracking=(enabled=false,path=\".\")," - "shared_cache=(chunk=10MB,name=,quota=0,reserve=0,size=500MB)," - "statistics=none,statistics_log=(json=false,on_close=false," - "sources=,timestamp=\"%b %d %H:%M:%S\",wait=0)," + "io_capacity=(total=0),json_output=[],log=(archive=true," + "os_cache_dirty_pct=0,prealloc=true,zero_fill=false)," + "lsm_manager=(merge=true,worker_thread_max=4)," + "operation_timeout_ms=0,operation_tracking=(enabled=false," + "path=\".\"),shared_cache=(chunk=10MB,name=,quota=0,reserve=0," + "size=500MB),statistics=none,statistics_log=(json=false," + "on_close=false,sources=,timestamp=\"%b %d %H:%M:%S\",wait=0)," "tiered_manager=(threads_max=8,threads_min=1,wait=0)," "tiered_storage=(local_retention=300,object_target_size=10M)," "timing_stress_for_test=,verbose=[]", - confchk_WT_CONNECTION_reconfigure, 30}, + confchk_WT_CONNECTION_reconfigure, 31}, {"WT_CONNECTION.rollback_to_stable", "", NULL, 0}, {"WT_CONNECTION.set_file_system", "", NULL, 0}, {"WT_CONNECTION.set_timestamp", "commit_timestamp=,durable_timestamp=,force=false," @@ -1475,9 +1480,9 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "file_manager=(close_handle_minimum=250,close_idle_time=30," "close_scan_interval=10),hash=(buckets=512,dhandle_buckets=512)," "hazard_max=1000,history_store=(file_max=0),in_memory=false," - "io_capacity=(total=0),log=(archive=true,compressor=," - "enabled=false,file_max=100MB,os_cache_dirty_pct=0,path=\".\"," - "prealloc=true,recover=on,zero_fill=false)," + "io_capacity=(total=0),json_output=[],log=(archive=true," + "compressor=,enabled=false,file_max=100MB,os_cache_dirty_pct=0," + "path=\".\",prealloc=true,recover=on,zero_fill=false)," "lsm_manager=(merge=true,worker_thread_max=4),mmap=true," "mmap_all=false,multiprocess=false,operation_timeout_ms=0," "operation_tracking=(enabled=false,path=\".\"),readonly=false," @@ -1492,7 +1497,7 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "transaction_sync=(enabled=false,method=fsync)," "use_environment=true,use_environment_priv=false,verbose=[]," "verify_metadata=false,write_through=", - confchk_wiredtiger_open, 58}, + confchk_wiredtiger_open, 59}, {"wiredtiger_open_all", "block_cache=(blkcache_eviction_aggression=1800," "cache_on_checkpoint=true,cache_on_writes=true,enabled=false," @@ -1515,9 +1520,9 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "file_manager=(close_handle_minimum=250,close_idle_time=30," "close_scan_interval=10),hash=(buckets=512,dhandle_buckets=512)," "hazard_max=1000,history_store=(file_max=0),in_memory=false," - "io_capacity=(total=0),log=(archive=true,compressor=," - "enabled=false,file_max=100MB,os_cache_dirty_pct=0,path=\".\"," - "prealloc=true,recover=on,zero_fill=false)," + "io_capacity=(total=0),json_output=[],log=(archive=true," + "compressor=,enabled=false,file_max=100MB,os_cache_dirty_pct=0," + "path=\".\",prealloc=true,recover=on,zero_fill=false)," "lsm_manager=(merge=true,worker_thread_max=4),mmap=true," "mmap_all=false,multiprocess=false,operation_timeout_ms=0," "operation_tracking=(enabled=false,path=\".\"),readonly=false," @@ -1532,7 +1537,7 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "transaction_sync=(enabled=false,method=fsync)," "use_environment=true,use_environment_priv=false,verbose=[]," "verify_metadata=false,version=(major=0,minor=0),write_through=", - confchk_wiredtiger_open_all, 59}, + confchk_wiredtiger_open_all, 60}, {"wiredtiger_open_basecfg", "block_cache=(blkcache_eviction_aggression=1800," "cache_on_checkpoint=true,cache_on_writes=true,enabled=false," @@ -1555,11 +1560,11 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "file_manager=(close_handle_minimum=250,close_idle_time=30," "close_scan_interval=10),hash=(buckets=512,dhandle_buckets=512)," "hazard_max=1000,history_store=(file_max=0),io_capacity=(total=0)" - ",log=(archive=true,compressor=,enabled=false,file_max=100MB," - "os_cache_dirty_pct=0,path=\".\",prealloc=true,recover=on," - "zero_fill=false),lsm_manager=(merge=true,worker_thread_max=4)," - "mmap=true,mmap_all=false,multiprocess=false," - "operation_timeout_ms=0,operation_tracking=(enabled=false," + ",json_output=[],log=(archive=true,compressor=,enabled=false," + "file_max=100MB,os_cache_dirty_pct=0,path=\".\",prealloc=true," + "recover=on,zero_fill=false),lsm_manager=(merge=true," + "worker_thread_max=4),mmap=true,mmap_all=false,multiprocess=false" + ",operation_timeout_ms=0,operation_tracking=(enabled=false," "path=\".\"),readonly=false,salvage=false,session_max=100," "session_scratch_max=2MB,session_table_cache=true," "shared_cache=(chunk=10MB,name=,quota=0,reserve=0,size=500MB)," @@ -1571,7 +1576,7 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "object_target_size=10M),timing_stress_for_test=," "transaction_sync=(enabled=false,method=fsync),verbose=[]," "verify_metadata=false,version=(major=0,minor=0),write_through=", - confchk_wiredtiger_open_basecfg, 53}, + confchk_wiredtiger_open_basecfg, 54}, {"wiredtiger_open_usercfg", "block_cache=(blkcache_eviction_aggression=1800," "cache_on_checkpoint=true,cache_on_writes=true,enabled=false," @@ -1594,11 +1599,11 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "file_manager=(close_handle_minimum=250,close_idle_time=30," "close_scan_interval=10),hash=(buckets=512,dhandle_buckets=512)," "hazard_max=1000,history_store=(file_max=0),io_capacity=(total=0)" - ",log=(archive=true,compressor=,enabled=false,file_max=100MB," - "os_cache_dirty_pct=0,path=\".\",prealloc=true,recover=on," - "zero_fill=false),lsm_manager=(merge=true,worker_thread_max=4)," - "mmap=true,mmap_all=false,multiprocess=false," - "operation_timeout_ms=0,operation_tracking=(enabled=false," + ",json_output=[],log=(archive=true,compressor=,enabled=false," + "file_max=100MB,os_cache_dirty_pct=0,path=\".\",prealloc=true," + "recover=on,zero_fill=false),lsm_manager=(merge=true," + "worker_thread_max=4),mmap=true,mmap_all=false,multiprocess=false" + ",operation_timeout_ms=0,operation_tracking=(enabled=false," "path=\".\"),readonly=false,salvage=false,session_max=100," "session_scratch_max=2MB,session_table_cache=true," "shared_cache=(chunk=10MB,name=,quota=0,reserve=0,size=500MB)," @@ -1610,7 +1615,7 @@ static const WT_CONFIG_ENTRY config_entries[] = {{"WT_CONNECTION.add_collator", "object_target_size=10M),timing_stress_for_test=," "transaction_sync=(enabled=false,method=fsync),verbose=[]," "verify_metadata=false,write_through=", - confchk_wiredtiger_open_usercfg, 52}, + confchk_wiredtiger_open_usercfg, 53}, {NULL, NULL, NULL, 0}}; int diff --git a/src/third_party/wiredtiger/src/conn/conn_api.c b/src/third_party/wiredtiger/src/conn/conn_api.c index 21b2f0675fa..ad38272d048 100644 --- a/src/third_party/wiredtiger/src/conn/conn_api.c +++ b/src/third_party/wiredtiger/src/conn/conn_api.c @@ -2007,13 +2007,27 @@ __wt_verbose_config(WT_SESSION_IMPL *session, const char *cfg[]) {"thread_group", WT_VERB_THREAD_GROUP}, {"timestamp", WT_VERB_TIMESTAMP}, {"tiered", WT_VERB_TIERED}, {"transaction", WT_VERB_TRANSACTION}, {"verify", WT_VERB_VERIFY}, {"version", WT_VERB_VERSION}, {"write", WT_VERB_WRITE}, {NULL, 0}}; + static const WT_NAME_FLAG jsontypes[] = { + {"error", WT_JSON_OUTPUT_ERROR}, {"message", WT_JSON_OUTPUT_MESSAGE}, {NULL, 0}}; + WT_CONFIG_ITEM cval, sval; WT_CONNECTION_IMPL *conn; WT_DECL_RET; const WT_NAME_FLAG *ft; + uint8_t flags; conn = S2C(session); + /* Check if JSON-encoded message strings are enabled, per event handler category. */ + WT_RET(__wt_config_gets(session, cfg, "json_output", &cval)); + flags = 0; + for (ft = jsontypes; ft->name != NULL; ft++) { + if ((ret = __wt_config_subgets(session, &cval, ft->name, &sval)) == 0 && sval.val != 0) + LF_SET(ft->flag); + WT_RET_NOTFOUND_OK(ret); + } + conn->json_output = flags; + WT_RET(__wt_config_gets(session, cfg, "verbose", &cval)); for (ft = verbtypes; ft->name != NULL; ft++) { diff --git a/src/third_party/wiredtiger/src/include/connection.h b/src/third_party/wiredtiger/src/include/connection.h index 89283c3cc19..c0a342ccaf9 100644 --- a/src/third_party/wiredtiger/src/include/connection.h +++ b/src/third_party/wiredtiger/src/include/connection.h @@ -555,6 +555,12 @@ struct __wt_connection_impl { /* Verbose settings for our various categories. */ WT_VERBOSE_LEVEL verbose[WT_VERB_NUM_CATEGORIES]; +/* AUTOMATIC FLAG VALUE GENERATION START 0 */ +#define WT_JSON_OUTPUT_ERROR 0x1u +#define WT_JSON_OUTPUT_MESSAGE 0x2u + /* AUTOMATIC FLAG VALUE GENERATION STOP 8 */ + uint8_t json_output; /* Output event handler messages in JSON format */ + /* * Variable with flags for which subsystems the diagnostic stress timing delays have been requested. */ diff --git a/src/third_party/wiredtiger/src/include/wiredtiger.in b/src/third_party/wiredtiger/src/include/wiredtiger.in index 1371a8b14f4..226b28bad49 100644 --- a/src/third_party/wiredtiger/src/include/wiredtiger.in +++ b/src/third_party/wiredtiger/src/include/wiredtiger.in @@ -2205,6 +2205,10 @@ struct __wt_connection { * throttled\, and in what proportion\, are made internally. The minimum non-zero setting * is 1MB., an integer between 0 and 1TB; default \c 0.} * @config{ ),,} + * @config{json_output, enable JSON formatted messages on the event handler interface. + * Options are given as a list\, where each option specifies an event handler category e.g. + * 'error' represents the messages from the WT_EVENT_HANDLER::handle_error method., a list\, + * with values chosen from the following options: \c "error"\, \c "message"; default \c [].} * @config{log = (, enable logging. Enabling logging uses three sessions from the * configured session_max., a set of related configuration options defined below.} * @config{    archive, automatically archive unneeded log files., a @@ -2981,6 +2985,10 @@ struct __wt_connection { * made internally. The minimum non-zero setting is 1MB., an integer between 0 and 1TB; default \c * 0.} * @config{ ),,} + * @config{json_output, enable JSON formatted messages on the event handler interface. Options are + * given as a list\, where each option specifies an event handler category e.g. 'error' represents + * the messages from the WT_EVENT_HANDLER::handle_error method., a list\, with values chosen from + * the following options: \c "error"\, \c "message"; default \c [].} * @config{log = (, enable logging. Enabling logging uses three sessions from the configured * session_max., a set of related configuration options defined below.} * @config{    archive, automatically archive unneeded log files., a boolean diff --git a/src/third_party/wiredtiger/src/support/err.c b/src/third_party/wiredtiger/src/support/err.c index 62ed921edf5..53a5a73a077 100644 --- a/src/third_party/wiredtiger/src/support/err.c +++ b/src/third_party/wiredtiger/src/support/err.c @@ -161,21 +161,167 @@ __wt_event_handler_set(WT_SESSION_IMPL *session, WT_EVENT_HANDLER *handler) remain -= __len; \ } while (0) +/* + * __eventv_unpack_json_str -- + * Unpack a string into JSON escaped format. Can be called with null destination for sizing. + */ +static size_t +__eventv_unpack_json_str(u_char *dest, size_t dest_len, char *src, size_t src_len) + WT_GCC_FUNC_ATTRIBUTE((cold)) +{ + size_t len, n, nchars; + u_char *q; + const char *p; + + nchars = 0; + q = dest; + + for (p = src, len = src_len; len > 0; p++, --len) { + n = __wt_json_unpack_char((u_char)*p, q, dest_len, false); + nchars += n; + if (q != NULL) { + dest_len -= n; + q += n; + } + } + + if (q != NULL) + *q = '\0'; + + return (nchars); +} + +/* + * __eventv_gen_msg -- + * Generate a formatted message. + */ +static int +__eventv_gen_msg(WT_SESSION_IMPL *session, char *buffer, size_t *buffer_len, bool is_json, + int error, const char *func, int line, const char *fmt, va_list ap) WT_GCC_FUNC_ATTRIBUTE((cold)) +{ + struct timespec ts; + WT_DECL_RET; + size_t len, msg_len, remain, remain_msg, unpacked_msg_len; + u_char *unpacked_json_str; + char msg_str[2 * 1024], *p, *p_msg, tid[128]; + const char *err, *prefix; + + p = buffer; + p_msg = msg_str; + unpacked_json_str = NULL; + + remain = *buffer_len; + remain_msg = sizeof(msg_str); + + if (is_json) + WT_ERROR_APPEND(p, remain, "{"); + + /* Timestamp and thread id. */ + __wt_epoch(session, &ts); + WT_ERR(__wt_thread_str(tid, sizeof(tid))); + if (is_json) { + WT_ERROR_APPEND(p, remain, "\"ts_sec\":%" PRIuMAX ",", (uintmax_t)ts.tv_sec); + WT_ERROR_APPEND( + p, remain, "\"ts_usec\":%" PRIuMAX ",", (uintmax_t)ts.tv_nsec / WT_THOUSAND); + WT_ERROR_APPEND(p, remain, "\"thread\":\"%s\",", tid); + } else { + WT_ERR(__wt_thread_str(tid, sizeof(tid))); + WT_ERROR_APPEND(p, remain, "[%" PRIuMAX ":%" PRIuMAX "][%s]", (uintmax_t)ts.tv_sec, + (uintmax_t)ts.tv_nsec / WT_THOUSAND, tid); + } + + /* Error prefix. */ + if ((prefix = S2C(session)->error_prefix) != NULL) { + if (is_json) + WT_ERROR_APPEND(p, remain, "\"session_err_prefix\":\"%s\",", prefix); + else + WT_ERROR_APPEND(p, remain, ", %s", prefix); + } + + /* Session dhandle name. */ + prefix = session->dhandle == NULL ? NULL : session->dhandle->name; + if (prefix != NULL) { + if (is_json) + WT_ERROR_APPEND(p, remain, "\"session_dhandle_name\":\"%s\",", prefix); + else + WT_ERROR_APPEND(p, remain, ", %s", prefix); + } + + /* Session name. */ + if ((prefix = session->name) != NULL) { + if (is_json) + WT_ERROR_APPEND(p, remain, "\"session_name\":\"%s\",", prefix); + else + WT_ERROR_APPEND(p, remain, ", %s", prefix); + } + + /* Message. */ + if (is_json) { + /* Format the content of the message into an intermediate buffer. */ + WT_ERROR_APPEND_AP(p_msg, remain_msg, fmt, ap); + + /* Escape any characters that are special for JSON. */ + msg_len = sizeof(msg_str) - remain_msg; + unpacked_msg_len = __eventv_unpack_json_str(NULL, 0, msg_str, msg_len); + WT_ERR(__wt_malloc(session, unpacked_msg_len + 1, &unpacked_json_str)); + WT_UNUSED(__eventv_unpack_json_str(unpacked_json_str, unpacked_msg_len, msg_str, msg_len)); + + WT_ERROR_APPEND(p, remain, "\"msg\":\""); + if (func != NULL) + WT_ERROR_APPEND(p, remain, "%s:%d:", func, line); + WT_ERROR_APPEND(p, remain, "%s", unpacked_json_str); + WT_ERROR_APPEND(p, remain, "\""); + } else { + WT_ERROR_APPEND(p, remain, ": "); + if (func != NULL) + WT_ERROR_APPEND(p, remain, "%s, %d: ", func, line); + WT_ERROR_APPEND(p, remain, ": "); + WT_ERROR_APPEND_AP(p, remain, fmt, ap); + } + + /* Error message. */ + if (error != 0) { + /* + * When the engine calls __wt_err on error, it often outputs an error message including the + * string associated with the error it's returning. We could change the calls to call + * __wt_errx, but it's simpler to not append an error string if all we are doing is + * duplicating an existing error string. + * + * Use strcmp to compare: both strings are nul-terminated, and we don't want to run past the + * end of the buffer. + */ + err = __wt_strerror(session, error, NULL, 0); + if (is_json) { + WT_ERROR_APPEND(p, remain, ","); + WT_ERROR_APPEND(p, remain, "\"error_str\":\"%s\",", err); + WT_ERROR_APPEND(p, remain, "\"error_code\":%d", error); + } else { + len = strlen(err); + if (WT_PTRDIFF(p, buffer) < len || strcmp(p - len, err) != 0) + WT_ERROR_APPEND(p, remain, ": %s", err); + } + } + + if (is_json) + WT_ERROR_APPEND(p, remain, "}"); + +err: + __wt_free(session, unpacked_json_str); + return (ret); +} + /* * __eventv -- * Report a message to an event handler. */ static int -__eventv(WT_SESSION_IMPL *session, bool msg_event, int error, const char *func, int line, - const char *fmt, va_list ap) WT_GCC_FUNC_ATTRIBUTE((cold)) +__eventv(WT_SESSION_IMPL *session, bool msg_event, bool is_json, int error, const char *func, + int line, const char *fmt, va_list ap) WT_GCC_FUNC_ATTRIBUTE((cold)) { - struct timespec ts; WT_DECL_RET; WT_EVENT_HANDLER *handler; WT_SESSION *wt_session; - size_t len, remain; - char *p, tid[128]; - const char *err, *prefix; + size_t remain; /* * We're using a stack buffer because we want error messages no matter @@ -186,7 +332,6 @@ __eventv(WT_SESSION_IMPL *session, bool msg_event, int error, const char *func, * Buffer placed at the end of the stack in case snprintf overflows. */ char s[4 * 1024]; - p = s; remain = sizeof(s); /* @@ -202,45 +347,8 @@ __eventv(WT_SESSION_IMPL *session, bool msg_event, int error, const char *func, if (session == NULL) goto err; - /* - * We have several prefixes for the error message: a timestamp and the process and thread ids, - * the database error prefix, the data-source's name, and the session's name. Write them as a - * comma-separate list, followed by a colon. - */ - __wt_epoch(session, &ts); - WT_ERR(__wt_thread_str(tid, sizeof(tid))); - WT_ERROR_APPEND(p, remain, "[%" PRIuMAX ":%" PRIuMAX "][%s]", (uintmax_t)ts.tv_sec, - (uintmax_t)ts.tv_nsec / WT_THOUSAND, tid); - - if ((prefix = S2C(session)->error_prefix) != NULL) - WT_ERROR_APPEND(p, remain, ", %s", prefix); - prefix = session->dhandle == NULL ? NULL : session->dhandle->name; - if (prefix != NULL) - WT_ERROR_APPEND(p, remain, ", %s", prefix); - if ((prefix = session->name) != NULL) - WT_ERROR_APPEND(p, remain, ", %s", prefix); - WT_ERROR_APPEND(p, remain, ": "); - - if (func != NULL) - WT_ERROR_APPEND(p, remain, "%s, %d: ", func, line); - - WT_ERROR_APPEND_AP(p, remain, fmt, ap); - - if (error != 0) { - /* - * When the engine calls __wt_err on error, it often outputs an error message including the - * string associated with the error it's returning. We could change the calls to call - * __wt_errx, but it's simpler to not append an error string if all we are doing is - * duplicating an existing error string. - * - * Use strcmp to compare: both strings are nul-terminated, and we don't want to run past the - * end of the buffer. - */ - err = __wt_strerror(session, error, NULL, 0); - len = strlen(err); - if (WT_PTRDIFF(p, s) < len || strcmp(p - len, err) != 0) - WT_ERROR_APPEND(p, remain, ": %s", err); - } + /* Format the message. */ + WT_ERR(__eventv_gen_msg(session, s, &remain, is_json, error, func, line, fmt, ap)); /* * If a handler fails, return the error status: if we're in the process of handling an error, @@ -306,7 +414,9 @@ __wt_err_func(WT_SESSION_IMPL *session, int error, const char *func, int line, c * return. */ va_start(ap, fmt); - WT_IGNORE_RET(__eventv(session, false, error, func, line, fmt, ap)); + WT_IGNORE_RET(__eventv(session, false, + session ? FLD_ISSET(S2C(session)->json_output, WT_JSON_OUTPUT_ERROR) : false, error, func, + line, fmt, ap)); va_end(ap); } @@ -326,7 +436,9 @@ __wt_errx_func(WT_SESSION_IMPL *session, const char *func, int line, const char * return. */ va_start(ap, fmt); - WT_IGNORE_RET(__eventv(session, false, 0, func, line, fmt, ap)); + WT_IGNORE_RET(__eventv(session, false, + session ? FLD_ISSET(S2C(session)->json_output, WT_JSON_OUTPUT_ERROR) : false, 0, func, line, + fmt, ap)); va_end(ap); } @@ -349,7 +461,9 @@ __wt_panic_func(WT_SESSION_IMPL *session, int error, const char *func, int line, * return. */ va_start(ap, fmt); - WT_IGNORE_RET(__eventv(session, false, error, func, line, fmt, ap)); + WT_IGNORE_RET( + __eventv(session, false, session ? FLD_ISSET(conn->json_output, WT_JSON_OUTPUT_ERROR) : false, + error, func, line, fmt, ap)); va_end(ap); /* @@ -368,8 +482,8 @@ __wt_panic_func(WT_SESSION_IMPL *session, int error, const char *func, int line, * I'm not confident of underlying support for a NULL. */ va_start(ap, fmt); - WT_IGNORE_RET( - __eventv(session, false, WT_PANIC, func, line, "the process must exit and restart", ap)); + WT_IGNORE_RET(__eventv(session, false, FLD_ISSET(conn->json_output, WT_JSON_OUTPUT_ERROR), + WT_PANIC, func, line, "the process must exit and restart", ap)); va_end(ap); #if defined(HAVE_DIAGNOSTIC) @@ -431,7 +545,9 @@ __wt_ext_err_printf(WT_EXTENSION_API *wt_api, WT_SESSION *wt_session, const char session = ((WT_CONNECTION_IMPL *)wt_api->conn)->default_session; va_start(ap, fmt); - ret = __eventv(session, false, 0, NULL, 0, fmt, ap); + ret = __eventv(session, false, + session ? FLD_ISSET(S2C(session)->json_output, WT_JSON_OUTPUT_ERROR) : false, 0, NULL, 0, fmt, + ap); va_end(ap); return (ret); } @@ -472,7 +588,9 @@ __wt_verbose_worker(WT_SESSION_IMPL *session, const char *fmt, ...) va_list ap; va_start(ap, fmt); - WT_IGNORE_RET(__eventv(session, true, 0, NULL, 0, fmt, ap)); + WT_IGNORE_RET(__eventv(session, true, + session ? FLD_ISSET(S2C(session)->json_output, WT_JSON_OUTPUT_MESSAGE) : false, 0, NULL, 0, + fmt, ap)); va_end(ap); } diff --git a/src/third_party/wiredtiger/test/suite/test_verbose01.py b/src/third_party/wiredtiger/test/suite/test_verbose01.py index 7bd7b542803..726989b6b0e 100755 --- a/src/third_party/wiredtiger/test/suite/test_verbose01.py +++ b/src/third_party/wiredtiger/test/suite/test_verbose01.py @@ -29,13 +29,13 @@ from suite_subprocess import suite_subprocess from contextlib import contextmanager -import wiredtiger, wttest -import re +from wtscenario import make_scenarios +import json, re, wiredtiger, wttest # Shared base class used by verbose tests. class test_verbose_base(wttest.WiredTigerTestCase, suite_subprocess): # The maximum number of lines we will read from stdout in any given context. - nlines = 30000 + nlines = 50000 def create_verbose_configuration(self, categories): if len(categories) == 0: @@ -43,12 +43,15 @@ class test_verbose_base(wttest.WiredTigerTestCase, suite_subprocess): return 'verbose=[' + ','.join(categories) + ']' @contextmanager - def expect_verbose(self, categories, patterns, expect_output = True): + def expect_verbose(self, categories, patterns, expect_json, expect_output = True): # Clean the stdout resource before yielding the context to the execution block. We only want to # capture the verbose output of the using context (ignoring any previous output up to this point). self.cleanStdout() # Create a new connection with the given verbose categories. verbose_config = self.create_verbose_configuration(categories) + # Enable JSON output if required. + if expect_json: + verbose_config += ",json_output=[message]" conn = self.wiredtiger_open(self.home, verbose_config) # Yield the connection resource to the execution context, allowing it to perform any necessary # operations on the connection (for generating the expected verbose output). @@ -66,7 +69,16 @@ class test_verbose_base(wttest.WiredTigerTestCase, suite_subprocess): # Test the contents of each verbose message, ensuring it satisfies the expected pattern. verb_pattern = re.compile('|'.join(patterns)) - for line in verbose_messages: + # To avoid truncated messages, slice out the last message string in the + for line in verbose_messages[:-1]: + # Check JSON validity + if expect_json: + try: + json.loads(line) + except Exception as e: + self.prout('Unable to parse JSON message: %s' % line) + raise e + self.assertTrue(verb_pattern.search(line) != None, 'Unexpected verbose message: ' + line) # Close the connection resource and clean up the contents of the stdout file, flushing out the @@ -80,7 +92,15 @@ class test_verbose_base(wttest.WiredTigerTestCase, suite_subprocess): # of the interface prior to the introduction of verbosity levels, ensuring 'legacy'-style # uses of the interface are still supported. class test_verbose01(test_verbose_base): + + format = [ + ('flat', dict(is_json=False)), + ('json', dict(is_json=True)), + ] + scenarios = make_scenarios(format) + collection_cfg = 'key_format=S,value_format=S' + # Test use cases passing single verbose categories, ensuring we only produce verbose output for the single category. def test_verbose_single(self): # Close the initial connection. We will be opening new connections with different verbosity settings throughout @@ -89,7 +109,7 @@ class test_verbose01(test_verbose_base): # Test passing a single verbose category, 'api'. Ensuring the only verbose output generated is related to # the 'api' category. - with self.expect_verbose(['api'], ['WT_VERB_API']) as conn: + with self.expect_verbose(['api'], ['WT_VERB_API'], self.is_json) as conn: # Perform a set of simple API operations (table creations and cursor operations) to generate verbose API # messages. uri = 'table:test_verbose01_api' @@ -102,7 +122,7 @@ class test_verbose01(test_verbose_base): # Test passing another single verbose category, 'compact'. Ensuring the only verbose output generated is related to # the 'compact' category. - with self.expect_verbose(['compact'], ['WT_VERB_COMPACT']) as conn: + with self.expect_verbose(['compact'], ['WT_VERB_COMPACT'], self.is_json) as conn: # Create a simple table to invoke compaction on. We aren't doing anything interesting with the table # such that the data source will be compacted. Rather we want to simply invoke a compaction pass to # generate verbose messages. @@ -117,7 +137,7 @@ class test_verbose01(test_verbose_base): self.close_conn() # Test passing multiple verbose categories, being 'api' & 'version'. Ensuring the only verbose output generated # is related to those two categories. - with self.expect_verbose(['api','version'], ['WT_VERB_API', 'WT_VERB_VERSION']) as conn: + with self.expect_verbose(['api','version'], ['WT_VERB_API', 'WT_VERB_VERSION'], self.is_json) as conn: # Perform a set of simple API operations (table creations and cursor operations) to generate verbose API # messages. Beyond opening the connection resource, we shouldn't need to do anything special for the version # category. @@ -132,7 +152,7 @@ class test_verbose01(test_verbose_base): def test_verbose_none(self): self.close_conn() # Testing passing an empty set of categories. Ensuring no verbose output is generated. - with self.expect_verbose([], [], False) as conn: + with self.expect_verbose([], [], self.is_json, False) as conn: # Perform a set of simple API operations (table creations and cursor operations). Ensuring no verbose messages # are generated. uri = 'table:test_verbose01_none' diff --git a/src/third_party/wiredtiger/test/suite/test_verbose02.py b/src/third_party/wiredtiger/test/suite/test_verbose02.py index 33ed31de26d..c7ad990d951 100755 --- a/src/third_party/wiredtiger/test/suite/test_verbose02.py +++ b/src/third_party/wiredtiger/test/suite/test_verbose02.py @@ -27,13 +27,21 @@ # OTHER DEALINGS IN THE SOFTWARE. # -import wiredtiger, wttest from test_verbose01 import test_verbose_base +from wtscenario import make_scenarios +import wiredtiger, wttest # test_verbose02.py # Verify basic uses of the verbose configuration API when categories and valid/invalid verbosity # levels are specified. class test_verbose02(test_verbose_base): + + format = [ + ('flat', dict(is_json=False)), + ('json', dict(is_json=True)), + ] + scenarios = make_scenarios(format) + collection_cfg = 'key_format=S,value_format=S' # Test use cases passing single verbose categories, ensuring we only produce verbose output for @@ -46,7 +54,7 @@ class test_verbose02(test_verbose_base): # Test passing a single verbose category, 'api' along with the verbosity level # WT_VERBOSE_DEBUG (1). Ensuring the only verbose output generated is related to the 'api' # category. - with self.expect_verbose(['api:1'], ['WT_VERB_API']) as conn: + with self.expect_verbose(['api:1'], ['WT_VERB_API'], self.is_json) as conn: # Perform a set of simple API operations to generate verbose API messages. uri = 'table:test_verbose01_api' session = conn.open_session() @@ -58,7 +66,7 @@ class test_verbose02(test_verbose_base): # At this time, there is no verbose messages with the category WT_VERB_API and the verbosity # level WT_VERBOSE_INFO (0), hence we don't expect any output. - with self.expect_verbose(['api:0'], ['WT_VERB_API'], False) as conn: + with self.expect_verbose(['api:0'], ['WT_VERB_API'], self.is_json, False) as conn: uri = 'table:test_verbose01_api' session = conn.open_session() session.create(uri, self.collection_cfg) @@ -72,7 +80,7 @@ class test_verbose02(test_verbose_base): # WT_VERBOSE_INFO (0) and WT_VERBOSE_DEBUG (1), we can test them both. cfgs = ['compact:0', 'compact:1'] for cfg in cfgs: - with self.expect_verbose([cfg], ['WT_VERB_COMPACT']) as conn: + with self.expect_verbose([cfg], ['WT_VERB_COMPACT'], self.is_json) as conn: # Create a simple table to invoke compaction on. We aren't doing anything # interesting with the table, we want to simply invoke a compaction pass to generate # verbose messages. @@ -91,7 +99,7 @@ class test_verbose02(test_verbose_base): # to those two categories. cfgs = ['api:1,version', 'api,version:1', 'api:1,version:1'] for cfg in cfgs: - with self.expect_verbose([cfg], ['WT_VERB_API', 'WT_VERB_VERSION']) as conn: + with self.expect_verbose([cfg], ['WT_VERB_API', 'WT_VERB_VERSION'], self.is_json) as conn: # Perform a set of simple API operations (table creations and cursor operations) to # generate verbose API messages. Beyond opening the connection resource, we # shouldn't need to do anything special for the version category. -- cgit v1.2.1