Bug#31464539: SET PERSISTED LOG_ERROR_SERVICES WAS RESTORED PREMATURELY

Issue:

Setting log_error_services ends the buffered logging phase and
begins the normal logging phase, with all and any services the
user may have configured.

SET PERSISTs are restored immediately before log_error_services
is set "traditionally" (i.e. initialized from the command-line
value if any, or set to the default otherwise), and the buffered
messages are flushed.

SET PERSISTed system variables are restored in the order they were
set.

This lets the user restore a persisted log_error_services first,
thereby ending buffered logging, and then restore other system
variables, which may result in messages. In that case, those
messages are logged right away (as full logging has become
available via the earlier setting of log_error_services).
The buffered events (which were thrown earlier, but not logged
yet) will then be flushed afterwards. This can lead to unexpected
ordering of the messages in the log, where messages resulting
from restoring PERSISTs are followed by messages logged earlier.

For this to happen, buffered logging must be used (e.g. with a
loadable log-service like the JSON-logger), the configuration
must be set with SET PERSIST (rather than regular configuration
files or command-line options), and a variable must be restored
after log_error_services and result in messages (either directly
to the error-log, or intended for a client but redirected to the
error log as no client is attached yet).

Solution:

If we flag log_error_services as PERSIST_AS_READONLY, it will be
restored via the command-line. That means that the value will be
set in the same one defined place no matter whether we're restoring
a PERSISTed system variable or using an option set from a configuration
file or from the command-line. It is important to remember that
PERSIST_AS_READONLY guarantees that the value is set on the command-line,
and set very early during start-up; there is however no guarantee that
the assignment will take effect immediately. In the present patch, using
PERSIST_AS_READONLY results in the value taking effect slightly later
(rather than earlier) than it would be as from a regular PERSIST.
In this case, we need PERSIST_AS_READONLY not because we need an
extraordinarily early assignment, but to prevent log_error_services
from being restored as a system-variable. It serves the enforce a
certain order on the restoring of the configuration during start-up,
rather than leaving it to the user.

Note:

While this takes a very specific configuration to become visible and
is perhaps closer to a wart than to a major issue, updating the
variable's timestamp (by re-PERSISTing it) to make it the latest to
be set (and thus the latest to be restored) should hotfix this:

> SET PERSIST log_error_services=@@global.log_error_services;

Approved by: Jens Even Blomsoy <[email protected]>

Author: Tatiana Azundris Nuernberg

mysql-test/r/log_components_split.result

@@ -182,6 +182,37 @@ FLUSH ERROR LOGS;
 { "prio" : 3, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: SELECT \"double dutch!\"", "time" : "1970-01-01T00:00:00.000000Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "Note" }
 { "prio" : 0, "subsystem" : "Server", "source_file" : "sql_parse.cc", "function" : "dispatch_command", "msg" : "Parser saw: SELECT \"double dutch!\"", "time" : "1970-01-01T00:00:00.000000Z", "ts" : 0, "thread" : 0, "err_symbol" : "ER_PARSER_TRACE", "SQL_state" : "XX999", "label" : "System" }
 
+#
+# Bug#31464539: SET PERSISTED LOG_ERROR_SERVICES WAS RESTORED PREMATURELY
+#
+
+# Set up logging via PERSISTs. Order of the PERSISTs matters!
+INSTALL COMPONENT "file://component_log_sink_json";
+RESET PERSIST;
+SET PERSIST log_error_verbosity=3;
+SET PERSIST log_error_services="log_filter_internal; log_sink_internal; log_sink_json";
+SET PERSIST innodb_monitor_enable=all;
+# Restart server and verify log configuration.
+# We should also receive a full JSON log of the start-up.
+# restart
+SELECT @@global.log_error_verbosity;
+@@global.log_error_verbosity
+3
+SELECT @@global.log_error_services;
+@@global.log_error_services
+log_filter_internal; log_sink_internal; log_sink_json
+SELECT @@global.innodb_monitor_enable;
+@@global.innodb_monitor_enable
+all
+# Reset PERSISTs.
+RESET PERSIST;
+SET GLOBAL log_error_services=DEFAULT;
+UNINSTALL COMPONENT "file://component_log_sink_json";
+# Log file analysis:
+SUCCESS!
+# Restart server with all defaults
+# restart
+
 ###
 ### done
 ###

mysql-test/t/log_components_split.test

@@ -159,6 +159,75 @@ EOF
 --remove_file $log_json_0_
 --remove_file $log_json_1_
 
+
+--echo
+--echo #
+--echo # Bug#31464539: SET PERSISTED LOG_ERROR_SERVICES WAS RESTORED PREMATURELY
+--echo #
+--echo
+
+--echo # Set up logging via PERSISTs. Order of the PERSISTs matters!
+INSTALL COMPONENT "file://component_log_sink_json";
+RESET PERSIST;
+SET PERSIST log_error_verbosity=3;
+SET PERSIST log_error_services="log_filter_internal; log_sink_internal; log_sink_json";
+SET PERSIST innodb_monitor_enable=all;
+
+--echo # Restart server and verify log configuration.
+--echo # We should also receive a full JSON log of the start-up.
+--source include/restart_mysqld.inc
+
+SELECT @@global.log_error_verbosity;
+SELECT @@global.log_error_services;
+SELECT @@global.innodb_monitor_enable;
+
+--echo # Reset PERSISTs.
+RESET PERSIST;
+SET GLOBAL log_error_services=DEFAULT;
+UNINSTALL COMPONENT "file://component_log_sink_json";
+
+--echo # Log file analysis:
+let GREP_FILE=$log_json_0_;
+
+perl;
+   use strict;
+   use File::stat;
+   my $file= $ENV{'GREP_FILE'} or die("grep file not set");
+
+   my $second_run=0;
+   my $seen_inno=0;
+   my $post_inno=0;
+
+   open(FILE, "$file") or die("Unable to open $file: $!");
+   while (<FILE>) {
+     my $line = $_;
+
+     # Ignore everything pre-shutdown
+     if ($line =~ /"ER_SERVER_SHUTDOWN_COMPLETE"/) {
+       $second_run=1; }
+
+     if ($second_run > 0) {
+       # Count un-buffered InnoDB messages.
+       if (!($line =~ /"buffered" : /) && ($line =~ /"subsystem" : "InnoDB"/)) {
+         $seen_inno++; }
+       #
+       if (($line =~ /"buffered" : /) && ($seen_inno > 0)) {
+         $post_inno++; }}}
+   close(FILE);
+
+   if ($post_inno > 0) {
+     print "FAIL: $post_inno buffered lines seen after $seen_inno unbuffered ones.\n"; }
+   else {
+     print "SUCCESS!\n"; }
+EOF
+
+# --remove_file $MYSQLD_DATADIR/mysqld-auto.cnf
+--remove_file $log_json_0_
+
+--echo # Restart server with all defaults
+--source include/restart_mysqld.inc
+
+
 --echo
 --echo ###
 --echo ### done

sql/sys_vars.cc

@@ -2427,10 +2427,10 @@ static bool fix_log_error_services(sys_var *self MY_ATTRIBUTE((unused)),
 static Sys_var_charptr Sys_log_error_services(
     "log_error_services",
     "Services that should be called when an error event is received",
-    GLOBAL_VAR(opt_log_error_services), CMD_LINE(REQUIRED_ARG),
-    IN_SYSTEM_CHARSET, DEFAULT(LOG_ERROR_SERVICES_DEFAULT), NO_MUTEX_GUARD,
-    NOT_IN_BINLOG, ON_CHECK(check_log_error_services),
-    ON_UPDATE(fix_log_error_services));
+    PERSIST_AS_READONLY GLOBAL_VAR(opt_log_error_services),
+    CMD_LINE(REQUIRED_ARG), IN_SYSTEM_CHARSET,
+    DEFAULT(LOG_ERROR_SERVICES_DEFAULT), NO_MUTEX_GUARD, NOT_IN_BINLOG,
+    ON_CHECK(check_log_error_services), ON_UPDATE(fix_log_error_services));
 
 static bool check_log_error_suppression_list(sys_var *self, THD *thd,
                                              set_var *var) {