WL#9323: Logging services: Improved error logging in 8.0
Affects: Server-8.0
—
Status: Complete
STRUCTURED LOGGING, BIRD'S EYE VIEW 1 The Status Quo The log interface accepts a single string sql_print_information("hi"); or rather, a printf-style format string, and the arguments needed for its % substitutions; the result of filling in those substitutions is the aforementioned single flat string: sql_print_information("Hi, I am MySQL, and I am %d years old!", 21); Depending on the destination (log file, syslog, Windows EventLog, ...), some other information (syslog facility, connection ID, process ID, ...) may appear the data data. 2 The Problem Whenever a new log destination or format is needed (e.g. JSON or XML log format, systemd journal log destination, etc.), the server needs to be modified. Customers cannot have customized logging; they need to accept our formats, and convert them as needed. To add insult to injury, the majority of the relevant information is encoded in an error-message that is easy for humans to parse, but much harder for machines to reliably and efficiently process. 3 The Future 3.1 Pluggable logging Logging shall be recreated as a framework for pluggable components/services (as defined in the framework specified in WL#4102). This will allow for customized components, implementing new logging formats, or even new kinds of log filtering within the process boundary of mysqld. Components could even add custom log items (for instance, on Linux a log-source might pull relevant information from /proc). Advantages: - Only what is needed gets loaded - Clients can create and maintain their own proprietary modules - Option to realize certain functionality as Enterprise-only components 3.2 Structured information Logging shall now use information of higher granularity. The primary concern is the adding of error numbers (for easier processing by machines than what just the flat error string allowed). Other info-bits shall be supported (e.g. component-name). The design attempts to be future-proof/extensible by allowing third-party log-sources to add "generic" key/value pairs. The structured information expressed by the new log-writers might look like so: XML log-entry:JSON log-entry: { "log_priority": 2, "subsystem": "parser", "SQL_state": "XX999", "source_file": "sql_parse", "MySQL_err_symbol": "ER_PARSER_TRACE", "log_message": "Parser saw: INSTALL COMPONENT \"file://component_log_sink_json\"", "log_label": "Note" } 3.3 Operation The new API accepts the submitted data, filters it (verbosity, rate-limiting, re-priotizing, etc.), and finally forwards the modified set to one or several log-writer services. The log-writers can eventually take many shapes (XML, JSON, ...). In the short term, the present ones (syslog, EventLog, flatfile) shall be re-implemented on top of the new model and service infastructure. JSON will additionally be available as the first sink that can handle structured entries (so that we will have a means of testing the new infrastructure). 4 Relationship with other work: error messages Error messages (sql_print_*()) should be switched over to the "richer" calls (with error codes etc.), and similar messages should be collapsed into a single "well-known" one. error messages Currently, if we wish to have a high priority message, we need to tag it "error" to prevent its being verbosity-filtered, even if an actual error has not occurred. The new design separates message priority and label ("Warning", "Error", etc.). Both coincide by default (with the label being derived from the priority), but they may be set them separately were necessary (and where freeform labeling is supported by the backend; syslog and EventLog do not). log info sources *** DEFERRED *** Implement an example log source that adds additional information about a client (where known) to error-log messages, such as _client_role and program_name. This component is not critical, and is not intended to be implemented and rolled out with the first tech demonstrator. log filtering (filtering engine) Re-implement current error logging options (verbosity, throttle, etc.) on top of the new infrastructure. For error-logging, the centralized filtering is to replace the current, decentral subclassing of the throttle class as well as other throttling solutions in the server (e.g. in rpl). log filtering (configuration engine) *** DEFERRED *** More of the new filtering service should be exposed to "power-DBAs" through a versatile configuration language. This component is not critical, and is not intended to be implemented and rolled out with the first tech demonstrator. log writing Writing error log messages: new service plugins to handle writing to log- file/syslog/etc. Re-implements current logging on top of the new service infrastructure and logging subsystem. Adds a new JSON log writer to demonstrate richer messages. service configuration When the configuration system for new services becomes available later, plugins should heed its specifications for their configuration (updating to that is currently beyond the scope of the above items, however). 2 parser XX999 sql_parse ER_PARSER_TRACE Parser saw: INSTALL COMPONENT "file://component_log_sink_xml" Note
R1: Implement a strong separation between creating an error event and how it is reported. When some error condition is encountered we give the facts to the error logging module without making any decisions about how to use this information. The facts are: Error number, severity (info, warning, error), component (e.g. server, innodb, replication, plugin), and optional arguments (like table names). R2: The error logging API will need to support variable number of arguments, like log(errno, severity, component, arg1, arg2,...). R3: Implement error logging (i.e. the actual writing of the log, as opposed to the submission and basic processing of the log event) as a pluggable module (loadable component). If possible it should also introduce an error logging service in the new service infrastructure usable by all other components. R4: Our default plugin implementation should support the same functionality as in 5.7. In addition it must map from error number to error text. R5: Our default implementation should have an option to format output in the JSON format (key, value). R6: Our default plugin implementation should implement filtering (i.e. "do not output warnings"). A filter configuration module can optionally be loaded for more control, allowing the filter rules to be defined by a DBA using SQL. R7: Our default plugin implementation should offer the DBA to change the error texts as there are complaints about poor text messages. The traditional mechanism of doing this in the error message file is still available (for translations and other bulk changes). When the filter configuration language becomes available, "real-time" changes should be supported by it. R8: The error logging service should be installed before other components so that it will be available to other components who want to log error messages. R9: The error logging service should not be effective before InnoDB is up and running and error texts are available to the component. We need a hard coded solution in the time period before InnoDB / system tables are available to the component. R10: The error logging service shall be able to "broadcast", i.e., it must be able to send its data to multiple services rather than just the default one (e.g. write the log data to both a log file and to syslog, as it can in 5.7).
WL#4102: Service registry and component infrastructure
WL#6667: Reimplement the password validation plugin API and plugin as a component
WL#6667: Reimplement the password validation plugin API and plugin as a component
please also see individual WL linked from this core document I-1 SQL syntax NO CHANGE I-2 Instrumentation NO CHANGE I-3 Error and warnings YES -- richer error/warning messages. (Writer that logs abitrary log fields required.) I-4 Install/Upgrade NO CHANGE I-5 Commercial plugins NO CHANGE I-6 Replication NO CHANGE I-7 Protocols NO CHANGE I-8 Security NO CHANGE I-9 Log files YES -- the error log may feature richer data, depending on filter configuration, presence of log sources, and a writer that can write the additional fields. Log- sinks provided by loadable modules will become available once the component framework is ready. I-10 MySQL clients NO CHANGE I-11 Auth plugins NO CHANGE I-12 Globalization NO CHANGE I-13 Configuration NO CHANGE (for now; this may be amended once per-component system variables become available) I-14 File formats NO CHANGE (except log files, see there) I-15 Plugins/APIs YES. Implements a service in the new component model that allows for the submission of rich logging info (key/value pairs). Calls services that implement the source/filter/sink APIs. I-16 Other programs NO CHANGE I-17 Storage engines NO CHANGE
This part is concerned with the built-in "core" of the new logger, namely the structuring of the information, and the submission thereof. For the loadable sinks, sources, filter language, and for the filtering engine, please refer to the individual documents specifying them. 1 Calling the logger 1.1 From old to new: Legacy calls As a first step, the legacy sql_print_*() functions are removed, and #defines are created for them to use the new framework: #define sql_print_information(...) log_errlog_formatted(INFORMATION_LEVEL, ## __VA_ARGS__) #define sql_print_warning(...) log_errlog_formatted(WARNING_LEVEL, ## __VA_ARGS__) #define sql_print_error(...) log_errlog_formatted(ERROR_LEVEL, ## __VA_ARGS__) "log_errlog_formatted()" in turn is a macro that automatically enriches the call with additional information that is cheap to synthesize, e.g. #define log_errlog_formatted(level, ...) log_message(LOG_TYPE_ERROR, LOG_ITEM_LOG_PRIO, level, LOG_ITEM_MSC_SUBSYS, LOG_SUBSYSTEM_TAG, LOG_ITEM_SRC_LINE, __LINE__, LOG_ITEM_SRC_FILE, MY_BASENAME, LOG_ITEM_LOG_MESSAGE, ## __VA_ARGS__) The idea here is three-fold: - this lets us change over the calls to the error-loggger in batches, rather than having to change them all at once - synthetic key/value pairs help us with testing the structure information framework, and the rich log-writers (XML, JSON, systemd journal, and so forth) - finally, it will alert us to all incidents of sql_print_*() not being used directly, but via a function pointer 1.2 The variadic interface In that last define, we also see our variadic function, log_message(). It accepts a list of "assignments" of the form -, , for "well-known" types, and - , , , for ad-hoc types (LOG_ITEM_GEN_*: generic string or integer, and so forth) As its last item, the list should have - an element of type LOG_ITEM_LOG_MESSAGE, containing a printf-style format string, followed by all variables necessary to satisfy the substitutions in that string OR - an element of type LOG_ITEM_LOG_LOOKUP, containing a MySQL error code, which will be looked up in the list or regular error messages, followed by all variables necessary to satisfy the substitutions in that string OR - an element of type LOG_ITEM_LOG_VERBATIM, containing a string that will be used directly, with no % substitutions Advantages of this interface: - simple log messages are still a one-liner, and a no-brainer - it's easy to transform legacy sql_print_*() calls to this interface with a simple #define - it is easy to expose this function as a service (the service framework is biased towards C-style calling conventions) 1.3 The low-level interface The variadic interface takes the submitted data and fills in a log_line struct (key/value pairs, and some clerical information). It then calls log_line_submit() with this struct. log_line_submit() in turn calls all eligible log-sources, log-filters, and log-sinks, then frees the used resources. A caller is free to forego the variadic interface, prepare a log_line themselves, and call log_line_submit() directly. This is somewhat cumbersome for individual calls however, and mostly interesting for creating alternatives to the variadic wrapper: 1.4 The high-level interface One such example is the fluent C++ style interface offered in mysqld that allows for calls of the form, LogErr(INFORMATION_LEVEL, ER_STARTUP, my_progname, server_version); - once again, we have hassle-free one-liners - additional protection against type errors or number-of-argument errors vis-a- vis the variadic interface - additional particles can be appended as needed, e.g. LogErr(ERROR_LEVEL, ER_FOO, myArg).tableName(t->alias).sourceFile(__FILE__); Within mysqld, this is the preferred format for new calls (as opposed to legacy ones) to the logger. Likewise, new loadable services are encouraged to prefer this interface wherever possible. 2 Broadcast log_line_submit() is to iterate over any log_services implementing sources, filters, and sinks requested in the new system variable, log_error_services, in the order specified therein. For support of FLUSH ERROR LOGS log_services may implement a flush/hup method() that will be called by log.cc's reopen_error_log() (to close/reopen file for log rotation, etc.). 3 Realpolitik Some functionality depending largely on configuration must needs be deferred until such a time as per-component system variables are available. 4 The APIs, en detail 4.1 C++ fluent API Example: LogErr(INFORMATION_LEVEL, ER_FOO, "er_foo arg1"); LogErr(ERROR_LEVEL, ER_FOO, myArg).tableName(t->alias) .stringValue("myKey", myVal); Specification: LogErr(prio, errcode [, args]){. } # This is pretty much the maximum set, I'm sure we can prune some. # We could just use the generic setters, but this gives us type # safety and readability. # These particles correspond to the list of item-types further below. particle ::= errcode(longlong) | errsymbol(const char *) | sqlstate(const char *) | os_errno(longlong) | os_errmsg(const char *) | subsys(const char *) | component(const char *) # as per new component model | user(const char *) | host(const char *) | thread(longlong) | query_id(longlong) | table_name(const char *) | prio(longlong) # a.k.a. "severity" | label(const char *) # usually derived from prio | timestamp(const char *) | suppressed(longlong) # "and x more lines (gagged)" | verbatim(const char *) # error message has already been prepared, any % are actual %, no format string (becomes a message item) | message(fmt, ...) # ad hoc message + arguments (becomes a message item) | lookup(errcode, ...) # well-known message number is looked up, then snprintf'd to put the arguments into the format string | float_value(key, float) # ad hoc float | int_value(key, longlong) # ad hoc integer | string_value(key, const # ad hoc string char *, size_t) | source_file(const char *) | source_line(longlong) | function(const char *) Basically, this C++ API is a friendly face of log_item_type, which defines the analogous LOG_ITEM_SQL_ERRCODE, LOG_ITEM_LOG_TIMESTAMP, etc. (see below for full list). The C++ API creates an array of key/value pairs, then calls the low level API with it. 4.2 The variadic C-style API This API has two intended uses: a) as a fallback API for services not implemented in C++ b) to help with the incremental conversion of sql_print_error|warning|information(), as those three legacy functions can easily be re#defined to the C-API, while throwing in some additional synthetic items (like source, line-number, etc.) for better testing. Its signature is log_message( {, }); for particle ::= , | , , /** item_type -- what to log LOG_ITEM_END should not be used in the variadic interface as submitting a log line without an actual message is discouraged. Instead LOG_ITEM_LOG_MESSAGE or LOG_ITEM_LOG_LOOKUP should be used as the last LOG_ITEM_* key-value pairs: - LOG_ITEM_LOG_MESSAGE can be used to submit an ad hoc message directly while debugging. - LOG_ITEM_LOG_LOOKUP asks for the given error number to be replaced by the associated error message (i.e. the error message for the error number will be looked up, and the LOOKUP item will be replaced by a MESSAGE one). In variadic submission, both ad hoc and well-known error messages are considered printf()-style format strings, and should be followed by any arguments/variables required by that format string. In some situations, the variadic interface will automatically generate some items ("If you cannot afford a timestamp, one will be provided for you."). If an item of the required type already exists, the submission interface should not generate another. Old-style plug-ins using my_plugin_log_message() will automatically be tagged with a default LOG_ITEM_MSC_COMPONENT of their plug-in name. Non-variadic interface In non-variadic submission (i.e. all functions accepting a log_line), LOG_ITEM_LOG_LOOKUP and LOG_ITEM_GEN_CSTRING are not valid item types, while LOG_ITEM_LOG_MESSAGE must be a string literal (i.e. any substitutions must already have taken place). */ LOG_ITEM_END = 0, /**< end of list, see above */ LOG_ITEM_LOG_TYPE = 1, /**< error log, etc. */ LOG_ITEM_SQL_ERRCODE = 2, /**< mysql error code (numeric) */ LOG_ITEM_SQL_ERRSYMBOL = 4, /**< mysql error code (symbolic) */ LOG_ITEM_SQL_STATE = 8, /**< SQL state */ LOG_ITEM_SYS_ERRNO = 16, /**< OS errno */ LOG_ITEM_SYS_STRERROR = 32, /**< OS strerror() */ LOG_ITEM_SRC_FILE = 64, /**< log called from file ... */ LOG_ITEM_SRC_LINE = 128, /**< log called from line ... */ LOG_ITEM_SRC_FUNC = 256, /**< log called from function ... */ LOG_ITEM_MSC_SUBSYS = 512, /**< log called from subsystem ... */ LOG_ITEM_MSC_COMPONENT = 1024, /**< log called from component ... */ LOG_ITEM_MSC_USER = 2048, /**< offending thread owned by ... */ LOG_ITEM_MSC_HOST = 4096, /**< responsible user on host ... */ LOG_ITEM_MSC_THREAD = 8192, /**< connection ID */ LOG_ITEM_SQL_QUERY_ID = 16384, /**< query ID */ LOG_ITEM_SQL_TABLE_NAME = 32768, /**< table name */ LOG_ITEM_LOG_PRIO = 65536, /**< log prority (error, warn, ...) */ LOG_ITEM_LOG_LABEL = 131072, /**< label, if unequal priority */ LOG_ITEM_LOG_VERBATIM = 262144, /**< the message, no % substitutions */ LOG_ITEM_LOG_MESSAGE = 524288, /**< the message, format string */ LOG_ITEM_LOG_LOOKUP = 1048576, /**< insert message by error-code */ LOG_ITEM_LOG_TIMESTAMP = 2097152, /**< ISO8601 timestamp */ LOG_ITEM_LOG_SUPPRESSED = 4194304, /**< "and ... more" throttled */ LOG_ITEM_GEN_FLOAT = 8388608, /**< float not otherwise specified */ LOG_ITEM_GEN_INTEGER = 16777216, /**< integer not otherwise specified */ LOG_ITEM_GEN_LEX_STRING = 33554432, /**< lex string not otherwise specified */ LOG_ITEM_GEN_CSTRING = 67108864 /**< C-string not otherwise specified */ } log_item_type; /* data type */ typedef enum enum_log_item_class { LOG_UNTYPED = 0, /**< undefined */ LOG_CSTRING = 1, /**< string (char * + \0; variadic API only) */ LOG_INTEGER = 2, /**< integer (long long) */ LOG_FLOAT = 3, /**< float (double) */ LOG_LEX_STRING = 4 /**< string (char *, size_t) */ } log_item_class; /* do we need to release any parts of the item after use? */ enum enum_log_item_free { LOG_ITEM_FREE_NONE = 0, LOG_ITEM_FREE_KEY = 1, LOG_ITEM_FREE_VALUE = 2 }; /* union: payload */ typedef union _log_item_data { longlong data_integer; double data_float; LEX_CSTRING data_string; } log_item_data; /* item key: for now, a C-string */ typedef const char *log_item_key; /* log item: key/value */ typedef struct _log_item { log_item_type type; log_item_class item_class; log_item_key key; log_item_data data; uint32 alloc; } log_item; 5 FUNCTIONS FOR FILTERS & SINKS: THE "log_builtins" SERVICE functions FOR filter/sink services (the "built-in" service) This is a set of the services the *server* provides to external components (sinks, filters, ...). Unfortunately for the time being, there are some more that should at some point be provided by other services. Since this is not yet the case, and we need certain basics to implement the external services, we temporarily provide them here in the interim. BEGIN_SERVICE_DEFINITION(log_builtins) // helper: get label string for given priority DECLARE_METHOD(const char *, label_from_prio, (int prio)); // helper: get (index of) entry for well-known log-item by type DECLARE_METHOD(int, wellknown_by_type, (log_item_type t)); // helper: get (index of) entry for well-known log-item by key DECLARE_METHOD(int, wellknown_by_name, (const char *key, size_t length)); // helper: get type from well-known log-item entry (by index) DECLARE_METHOD(log_item_type, wellknown_get_type, (uint i)); // helper: get name from well-known log-item entry (by index) DECLARE_METHOD(const char *, wellknown_get_name, (uint i)); // helper: check well-known log-item (by index): do key/type/class add up? DECLARE_METHOD(int, item_inconsistent, (log_line *ll, uint i)); // helpers: predicates to find out about types and classes DECLARE_METHOD(bool, item_generic_type, (log_item_type t)); DECLARE_METHOD(bool, item_string_class, (log_item_class c)); DECLARE_METHOD(bool, item_numeric_class, (log_item_class c)); /** Create new log item with key name "key", and allocation flags of "alloc" (see enum_log_item_free). Will return NULL on failure, or a pointer to the item's log_item_data struct for convenience otherwise. This is mostly interesting for filters and other services that create items that are not part of a log_line; sources etc. that intend to create an item for a log_line (the more common case) should usually use the below line_item_set_with_key() which creates an item (like this function does), but also correctly inserts it into a log_line. */ DECLARE_METHOD(log_item_data *, item_set_with_key, (log_item *li, log_item_type t, const char *key, uint32 alloc)); /** Create new log item in log line "ll", with key name "key", and allocation flags of "alloc" (see enum_log_item_free). Will return NULL on failure, or a pointer to the item's log_item_data struct for convenience otherwise. On success, the number of registered items on the log line is also increased. For more information, see implementation. */ DECLARE_METHOD(log_item_data *, line_item_set_with_key, (log_line *ll, log_item_type t, const char *key, uint32 alloc)); /* Create a new log item of well-known type "t" in log line "ll". Will return NULL on failure, or a pointer to the item's log_item_data struct for convenience otherwise. On success, the number of registered items on the log line is also increased. For more information, see implementation. */ DECLARE_METHOD(log_item_data *, line_item_set, (log_line *ll, log_item_type t)); /* Check whether there is room left in the the log line */ DECLARE_METHOD(bool, line_full, (log_line *ll)); /* Submit a log line for processing (calling all applicable sources, filters, and sinks on it, then freeing all data marked allocated). This interface is intended to facilitate the building of submission interfaces other than the variadic message() one below. See the example fluent C++ Log() wrapper for an example of how to leverage it. */ DECLARE_METHOD(int, line_submit, (log_line *ll)); /* Submit a log-message for log "log_type". The variadic list accepts a list of "assignments" of the form - , , for well-known types, and - , , , for ad-hoc types (LOG_ITEM_GEN_*) As its last item, the list should have - an element of type LOG_ITEM_LOG_MESSAGE, containing a printf-style format string, followed by all variables necessary to satisfy the substitutions in that string OR - an element of type LOG_ITEM_LOG_LOOKUP, containing a MySQL error code, which will be looked up in the list or regular error messages, followed by all variables necessary to satisfy the substitutions in that string OR - an element of type LOG_ITEM_LOG_VERBATIM, containing a string that will be used directly, with no % substitutions */ DECLARE_METHOD(int, message, (int log_type, ...)); /* escape \0 bytes, add \0 terminator. for log-writers and other sinks that terminator in an API using C-strings. */ DECLARE_METHOD(int, sanitize, (log_item *li)); DECLARE_METHOD(const char *, errmsg_by_errcode, (int mysql_errcode)); DECLARE_METHOD(longlong, errcode_by_errsymbol, (const char *sym)); END_SERVICE_DEFINITION(log_builtins) BEGIN_SERVICE_DEFINITION(log_builtin_filter) // run built-in filter, get/set its configuration DECLARE_METHOD(int, filter_run, (log_line *li)); DECLARE_METHOD(int, filter_get, (char **rules, size_t *len)); DECLARE_METHOD(int, filter_set, (const char *rules)); DECLARE_METHOD(void *, filter_ruleset_get, ()); DECLARE_METHOD(void, filter_ruleset_drop, ()); DECLARE_METHOD(void *, filter_rule_init, ()); END_SERVICE_DEFINITION(log_builtin_filter) We also have a few functions that the implementation needs, but that the logging services shouldn't really have to provide. Unfortunately since we're the first user of the component framework, nobody provides these common convenience functions yet, so we provide them in the interim: BEGIN_SERVICE_DEFINITION(log_builtins_tmp) /* Get connection attributes (as set on connection by the client library, optionally enrichted by attributes submitted by the client via mysql_options4(). Fetch attributes for "num" many "keys" and add them to "ll". If num == 0, get all available attributes. */ DECLARE_METHOD(int, get_connectattrs, (log_line *ll, size_t num, const char **keys)); // write errstream. will likely go away once we have variables. DECLARE_METHOD(void, write_errstream, (const char *buffer, size_t length)); // Are we shutting down yet? Windows EventLog needs to know. ### TBD DECLARE_METHOD(bool, connection_loop_aborted, (void)); END_SERVICE_DEFINITION(log_builtins_tmp) BEGIN_SERVICE_DEFINITION(log_builtins_string) // snprintf and friends. will hopefully be provided by // another service in the end // alloc (len+1) bytes, then copy len bytes from fm, and \0 terminate // like my_strndup(), and unlike strndup(), \0 in input won't end copying DECLARE_METHOD(char *, strndup, (const char *fm, size_t len)); // free allocated memory DECLARE_METHOD(void, free, (void *ptr)); // replace all % in format string with variables from list (my_vsnprintf()) DECLARE_METHOD(size_t, substitutev, (char *to, size_t n, const char* fmt, va_list ap)); // replace all % in format string with variables from list (my_snprintf()) DECLARE_METHOD(size_t, substitute, (char *to, size_t n, const char* fmt, ...)); END_SERVICE_DEFINITION(log_builtins_tmp) 6 FALLBACK The loadable modules will be available very shortly after the component framework is; the goal is to have them available to other loadable services from the get-go. Error logging per se must be available even earlier, as errors may occur before the component framework is ready; for this, we use a streamlined, non-component version of the logging in 5.7 that writes to a log file in the fixed, traditional MySQL error log format.
Copyright (c) 2000, 2024, Oracle Corporation and/or its affiliates. All rights reserved.