WL#9323: Logging services: Improved error logging in 8.0

Affects: Server-8.0   —   Status: Complete   —   Priority: Medium


1  The Status Quo

The log interface accepts a single string


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 


- 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:
  <log_message>Parser saw: INSTALL COMPONENT 

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 
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).
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

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).
please also see individual WL linked from this core document

I-1  SQL syntax


I-2  Instrumentation


I-3  Error and warnings

YES -- richer error/warning messages.
(Writer that logs abitrary log fields required.)

I-4  Install/Upgrade


I-5  Commercial plugins


I-6  Replication


I-7  Protocols


I-8  Security


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


I-11 Auth plugins


I-12 Globalization


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


I-17 Storage engines

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, ## 

#define sql_print_warning(...) log_errlog_formatted(WARNING_LEVEL, ## 

#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, 

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

    - <log_item_type>, <value>,         for "well-known" types, and

    - <log_item_type>, <key>, <value>,  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


    - 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


    - 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


  LogErr(INFORMATION_LEVEL, ER_FOO, "er_foo arg1");
  LogErr(ERROR_LEVEL, ER_FOO, myArg).tableName(t->alias)
                                    .stringValue("myKey", myVal);


  LogErr(prio, errcode [, args]){.<particle>}

  #  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
                                             <errcode> 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
   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(<log_type> {, <particle>});


  particle ::=   <wellknown_item_type>,             <item_value>
               | <generic_item_type>,   <item_key>, <item_value>

  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,

/* 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;


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


  // 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
    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
    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
    - <log_item_type>, <value>,         for well-known types, and
    - <log_item_type>, <key>, <value>,  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


    - 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


    - 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));



  // 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, ());


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:

    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));

  // 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, ...));



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.