Error Logging in MySQL 8

Although only available as a Release Candidate, MySQL 8 is already proving itself to be a huge leap forward in many regards. Error logging is no exception. The MySQL development team just announced that they have redesigned the error logging subsystem to use a new component architecture.

The redesign will allow the filtering of log events, as well as the routing of error log output to multiple destinations, via the enabling of multiple sink components.  This will make it possible to send error log events to third-party systems for additional formatting and analysis.

In today’s blog, we’ll explore how to employ MySQL 8’s component-based error logging to achieve a variety of logging configurations. Note that all this is specific for MySQL 8 and is not available in earlier versions and also not in MariaDB. However, MariaDB has an option to write the error log to the system “syslog” on systemd-based Linux variants – what includes all common Linux distributions released in the last few years. This option is not available in MySQL.

Component Architecture

MySQL Server now includes a component-based architecture.  This will facilitate the management of server capabilities through the installing and uninstalling of specific components.

The Component-based architecture is more modular in that components only interact with each other through the services they provide.  The services provided by components are available to the server as well as to other components.

With respect to the error log, a log component can be a filter or a sink:

• A filter processes log events, to add, remove, or modify individual event fields, or to delete events entirely.
• A sink is a destination (writer) for log events. Typically, a sink processes log events into log messages that have a particular format and writes these messages to its associated output, such as a file or the system log.

You can view the error log configuration by querying the global_variables table.  Error log variables are prefixed with “log_error_”:

select * from global_variables where VARIABLE_NAME like 'log_error_%';

+---------------------+----------------------------------------+
| VARIABLE_NAME       | VARIABLE_VALUE                         |
+---------------------+----------------------------------------+
| log_error_services  | log_filter_internal; log_sink_internal |
| log_error_verbosity | 2                                      |
+---------------------+----------------------------------------+

The server executes filters and sinks in the log_error_services value in the order they are listed.  By default, log events will first pass through log_filter_internal (the built-in filter component), followed by log_sink_internal (the built-in log writer component).

Component Types

Available log components reside in the lib/plugins directory and have a .so extension on Linux (and a .dll extension on Windows):

• component_log_filter_dragnet.so
• component_log_sink_json.so
• component_log_sink_syseventlog.so
• component_log_sink_test.so

To load a component, you refer to its URN. This is ‘file://‘ + the component filename without the .so extension.  Each component’s respective URN is listed in the next section.

• Error Log Filter Components

Error log filter components implement filtering of error log events.  If no filter component is enabled, no filtering occurs. Otherwise, any enabled filter component affects log events only for components listed later in the log_error_services variable.

There are 2 log filter components:

The log_filter_internal Component

It implements filtering based on the log_error_verbosity system variable setting.  This component is built in so it does not need to be loaded via INSTALL COMPONENT before use.

Note that, although log_error_verbosity affects the log_filter_internal component, log_error_verbosity has no effect on logging if log_filter_internal is not enabled.

The log_filter_dragnet Component

It implements filtering based on the rules defined by the dragnet.log_error_filter_rules system variable setting.   Its URN is “file://component_log_filter_dragnet”.

• Error Log Sink Components

Error log sink components are writers that implement error log output. If no sink component is enabled, no log output occurs.

Some sink component descriptions refer to the default error log destination. This is the console or a file and is indicated by the fault of the log_error system variable.

There are 4 log sink components:

The log_sink_internal Component

It implements traditional error log message output format. This component is built in so it does not need to be loaded via INSTALL COMPONENT before use.  Output is routed to the default error log destination.

The log_sink_json Component

It implements JSON-format error logging.  Its URN is “file://component_log_sink_json”.  The JSON log writer determines its output destination based on the default error log destination, which is given by the log_error system variable:

The log_sink_syseventlog Component

It implements error logging to the system log. This is the Event Log on Windows, and syslog on UNIX and UNIX-like systems, such as Linux. Its URN is “file://component_log_sink_syseventlog”.  Output is written to the system log rather than the default error log destination.

The log_sink_test Component

It’s intended for internal use in writing test cases and is not recommended for production use. Its URN is “file://component_log_sink_test”.  The output destination is the default error log.

Enabling a Log Component

To enable a log component, you would first load it using INSTALL COMPONENT, then list the component in the log_error_services value.

For example, to use the system log writer (log_sink_syseventlog) instead of the default writer (log_sink_internal), we would first load the writer component, then modify the log_error_services value:

INSTALL COMPONENT 'file://component_log_sink_syseventlog';
SET GLOBAL log_error_services = 'log_filter_internal; log_sink_syseventlog';

One of the great things about the new Error Log architecture is that it’s possible to configure multiple log writers to send output to multiple destinations. For instance, to enable the system log writer in addition to the default writer, set the log_error_services value like so:

SET GLOBAL log_error_services = 'log_filter_internal; log_sink_internal; log_sink_syseventlog';

Here’s another example to load the json component writer:

INSTALL COMPONENT 'file://component_log_sink_json';

SET GLOBAL log_error_services = 'log_filter_internal; log_sink_internal; log_sink_json';

mysql> select * from global_variables where VARIABLE_NAME like 'log_error_%';

+---------------------+-------------------------------------------------------+
| VARIABLE_NAME       | VARIABLE_VALUE                                        |
+---------------------+-------------------------------------------------------+
| log_error_services  | log_filter_internal; log_sink_internal; log_sink_json |
| log_error_verbosity | 2                                                     |
+---------------------+-------------------------------------------------------+

A few more things to keep in mind regarding the json writer:

• If log_error names a file, the JSON writer bases output file naming on that file name, plus a numbered .NN.json suffix, with NN starting at 00. For example, if log_error is “my_log_file”, successive instances of log_sink_json named in the log_error_services value write to my_log_file.00.json, my_log_file.01.json, and so on.
• If log_error is set to stderr, the JSON writer writes to the console by default.  Even if log_json_writer is named multiple times in the log_error_services value, they all write to the console, which is not terribly useful.

Configuring a Log Component to be enabled at Server Startup

In most cases, you’ll want your error logging configuration to persist across server restarts.  This can be achieved in a couple of ways:

1. Load the component using INSTALL COMPONENT. This registers it in the mysql.component system table so that the server loads the component automatically for subsequent startups.
2. Set the log_error_services value at startup to include the component name. You can set the value in the server my.cnf file.

As an example, suppose that you wanted to configure your MySQL server to use the JSON log writer (log_sink_json) in addition to the built-in log filter and writer (log_filter_internal, log_sink_internal). First load the JSON writer:

INSTALL COMPONENT 'file://component_log_sink_json';

Then, in the my.cnf file, set log_error_services to take effect at server startup:

[mysqld]
log_error_services='log_filter_internal; log_sink_internal; log_sink_json'

SET PERSIST log_error_services = 'log_filter_internal; log_sink_internal; log_sink_json';

Either will work, but note that values set in my.cnf only take effect at the next restart, while those set using SET PERSIST take effect immediately, as well as for subsequent restarts.

Uninstalling a Log Component

To uninstall a log component, use the UNINSTALL COMPONENT command.

For example, to revert to using only the default writer and unload the system log writer, execute these statements:

SET GLOBAL log_error_services = 'log_filter_internal; log_sink_internal;
UNINSTALL COMPONENT 'file://component_log_sink_syseventlog';

Error Log Message Formats

Each error log component writes messages to its destination using its own individual output format, although other factors such as system variables, may also influence the content of the messages.

For all log writers, the ID included in error log messages is that of the thread within the mysqld process responsible for writing the message (the connection thread ID). This indicates which part of the server produced the message, and is consistent with general query log and slow query log messages, which also include the connection thread ID.

Besides the common ID field, log_sink_internal, log_sink_json, and log_sink_syseventlog each employ their own output format.

Output Format for log_sink_internal

This log writer produces the traditional error log output using this format:

timestamp thread_id [severity] [err_code] [subsystem] message1

Note that the square bracket characters [ … ] are literal characters that appear in the message format and do not indicate that fields are optional, as they would in function parameter notation.

The [err_code] and [subsystem] are new fields that were added in MySQL 8.0.4 and 8.0.5, respectively. Hence, they will be absent from logs generated by older servers.  The err_code is a string value as it is made up of alphanumeric characters.

Here’s some example output:

2018-03-29T14:22:01.538083Z 0 [Note] [MY-012487] [InnoDB] InnoDB: DDL log recovery : begin

2018-03-29T14:22:01.538083Z 0 [Warning] [MY-010068] [Server] CA certificate /var/mysql/sslinfo/mycert.pem is self signed.

2018-03-29T14:22:01.538083Z 4 [Note] [MY-010051] [Server] Event Scheduler: scheduler thread started with id 4

2018-03-29T14:22:01.538083Z 0 [Note] [MY-010253] [Server] IPv6 is available.

Output Format for log_sink_json

The JSON-format log writer produces messages as JSON objects that contain key/value pairs. For example:

{ "prio": 3, "err_code": 10051, "subsystem": "Server",

  "source_file": "event_scheduler.cc", "function": "run",

  "msg": "Event Scheduler: scheduler thread started with id 4",

  "time": "2018-03-22T12:35:47.669397Z", "thread": 4,

  "err_symbol": "ER_SCHEDULER_STARTED", "SQL_state": "HY000",

  "label": "Note" }

Notice that the content is produced as a one line string, without line breaks.

Output Format for log_sink_syseventlog

The system log writer produces output that conforms to the specific system log format used on the local platform, i.e. the Windows Event Log.

Factors Affecting Error Log Format

As mentioned above, there are a couple of factors that may influence the content of Error Log messages:

• information available to the log writer: If a log filter component executed prior to the writer component removes a log event attribute for whatever reason, that attribute will no longer be available for writing.
• log_timestamps system variable: The log_timestamps system variable controls the time zone of timestamps in messages written to all logs, including the error log, general query log and slow query log files. Permitted values include “UTC” (the default) and “SYSTEM” (local system time zone).

Using Rule-based Error Log Filtering

MySQL 8’s new error log service allows you to use components to filter the events according to your own rules, using the log_filter_dragnet component.

Usually, the error log configuration includes one log filter component and one or more log writer components. As mentioned in Error Log Filter Components section, MySQL includes two log filter components: log_filter_internal and log_filter_dragnet.

Priority vs. Rules Based Filtering

The log_filter_internal component employs priority filtering based on the log_error_verbosity value.

Permitted log_error_verbosity values are:

• 1: log errors only
• 2: log errors and warnings
• 3: log errors, warnings, and notes

The log_filter_internal system variable is built in and enabled by default, but can be disabled. In the disabled state, changes to log_error_verbosity have no effect.

Important system messages about non-error situations are sent to the error log regardless of the log_error_verbosity value. These messages include startup and shutdown messages, and certain significant changes to settings.

If log_error_verbosity is set to 2 or greater, the server logs messages about statements that are unsafe for statement-based logging.  In general, a statement is considered “safe” if it deterministic, i.e. always produces the same result for the same input, and “unsafe” if it is not.  For example, statements containing system functions that may return a different value on slave such as FOUND_ROWS(), GET_LOCK(), IS_FREE_LOCK(), etc., would be considered nondeterministic, and thus, unsafe.  Conversely, some nondeterministic functions, including CONNECTION_ID(), CURDATE(), CURRENT_DATE(), etc., are treated as safe for purposes of logging and replication. In addition, statements using results from floating-point math functions—which are hardware-dependent—are always considered unsafe.

If the value is 3, the server logs everything, from serious errors to aborted connections and access-denied errors for new connection attempts.

Filtering rules for the log_filter_dragnet component are defined by setting the dragnet.log_error_filter_rules system variable.

To enable the log_filter_dragnet filter, first load the filter component, then modify the log_error_services value. The following example adds your custom rule set first in the chain, and the JSON log writer last:

INSTALL COMPONENT 'file://component_log_filter_dragnet'

SET GLOBAL log_error_services = 'log_filter_dragnet; 

log_sink_internal; log_sink_json';

A rule set consists of zero or more rules, where each rule is an IF statement terminated by a period (.) character.  If the variable value is empty (zero rules), no filtering occurs.

Here’s a rule set that drops information events, and, for other events, removes the source_line field:

SET GLOBAL dragnet.log_error_filter_rules =

  'IF prio>=INFORMATION THEN drop. IF EXISTS source_line THEN unset source_line.';

This rule limits information events to no more than one per 60 seconds:

SET GLOBAL dragnet.log_error_filter_rules = 

  'IF prio>=INFORMATION THEN throttle 1/60.';

Like other error-logging system variables, the log_filter_dragnet filter and dragnet.log_error_filter_rules can be enabled at server startup.  To make your rule set persist across server restarts, you should assign dragnet.log_error_filter_rules using SET PERSIST, as opposed to SET GLOBAL, as we did here.  Alternatively, you can also add the setting to the server option file. See the Configuring a Log Component to be enabled at Server Startup section above for instructions.

To turn off your custom filtering, you would remove the log_filter_dragnet filter from the set of error logging components, usually by setting a different and/or default filter component (rather than no filter component). For example:

SET GLOBAL log_error_services = 'log_filter_internal; log_sink_internal';

Don’t forget to use SET PERSIST if you want the setting to persist across server restarts!

Finally, uninstall the filter log_filter_dragnet component:

UNINSTALL COMPONENT 'file://component_log_filter_dragnet';

Conclusion

MySQL 8’s new component-based error logging architecture opens up a world of possibilities for customized error logging and routing.  In a future blog, we’ll learn how to analyze error log messages using the Monyog MySQL Monitoring Tool.