Eine neue Fehlerkultur… die MySQL „Error-Log“-Tabelle

Fehler machen und verstehen… 

Ab der Version 8.0.22. kann auf die aktuellen Inhalte, quasi über eine Art „Online-View", über die Tabelle „performance_schema.error_log" zugegriffen werden.

mysql> desc error_log;
+------------+-----------------------------------------+------+-----+---------+-------+
| Field      | Type                                    | Null | Key | Default | Extra |
+------------+-----------------------------------------+------+-----+---------+-------+
| LOGGED     | timestamp(6)                            | NO   | PRI | NULL    |       |
| THREAD_ID  | bigint unsigned                         | YES  | MUL | NULL    |       |
| PRIO       | enum('System','Error','Warning','Note') | NO   | MUL | NULL    |       |
| ERROR_CODE | varchar(10)                             | YES  | MUL | NULL    |       |
| SUBSYSTEM  | varchar(7)                              | YES  | MUL | NULL    |       |
| DATA       | text                                    | NO   |     | NULL    |       |
+------------+-----------------------------------------+------+-----+---------+-------+
6 rows in set (0.2861 sec) 

Die Tabelle beinhaltet exakt dieselben Informationen, wie die Einträge der bekannten ASCII-Log-Datei.

Über das neue „SQL-Interface" in die Error-Log Welt können jetzt natürlich komfortable Auswertungen erfolgen:

mysql> select count(*), error_code, prio from error_log group by error_code, prio order by 1,3;
…
|        4 | MY-011492  | System  |
|        4 | MY-011493  | Warning |
|        4 | MY-011494  | Warning |
|        4 | MY-011499  | Warning |
|        4 | MY-011069  | Warning |
|       11 | MY-011503  | System  |
|     9669 | MY-013360  | Warning |
+----------+------------+---------+ 

Schauen wir uns einmal die jüngsten drei Fehlermeldungen des Systems an: 

mysql> select prio, error_code, substr(data, 1,20)  from error_log order by logged desc limit 3;
+---------+------------+----------------------+
| prio    | error_code | substr(data, 1,20)   |
+---------+------------+----------------------+
| Warning | MY-013360  | Plugin sha256_passwo |
| Warning | MY-013360  | Plugin sha256_passwo |
| Warning | MY-013360  | Plugin sha256_passwo |
+---------+------------+----------------------+
3 rows in set (0.0081 sec) 

Auf diesem System scheint sich noch jemand mit einem veralteten Password-Algorithmus anmelden zu wollen (Error-Code „MY-013360"). Gesetzt den Fall, dass uns dieses Problem bekannt ist und wir es gerne ignorieren würden, steht eine entsprechende Systemvariable bereit, über welche sich Fehlermeldungen filtern lassen können: 

mysql> set global log_error_suppression_list="MY-013360"; 

Ab diesem Moment wird der Fehler „MY-013360" nicht mehr verarbeitet. Natürlich können durch Kommata getrennt weitere Fehler-Code berücksichtig werden. 

Schiffe Fehler versenken… 

Der interne Fehlerprozess besteht in den aktuellen 8er-Version nun aus einem zweistufigen, konfigurierbaren (!) Prozess:

1. Fehler filtern
2. Fehler schreiben

Was innerhalb dieser beiden Schritte passiert, wird über die Variable „log_error_services" bestimmt:

mysql> show variables like '%error%serv%';
+--------------------+----------------------------------------+
| Variable_name      | Value                                  |
+--------------------+----------------------------------------+
| log_error_services | log_filter_internal; log_sink_internal |
+--------------------+----------------------------------------+
1 row in set (0.0033 sec) 

In unserem Beispiel kümmert sich das Plugin „log_filter_internal" auf Basis von „log_error_supression_list" um das Filtern der Fehlermeldungen. „log_sink_internal" ist für die Speicherung der Fehlermeldungen im „error_log" verantwortlich. Das Wort „Plugin" stellt bereits in Aussicht, dass hier Veränderungen möglich sind.

So kann beispielsweise die „Datensenke" verändert und sogar erweitert werden. Bevor jedoch andere Plugins genutzt werden können, müssen diese geladen werden.

mysql> INSTALL COMPONENT 'file://component_log_sink_json‘;
Query OK, 0 rows affected (0.09 sec)

mysql> INSTALL COMPONENT 'file://component_log_sink_syseventlog';
Query OK, 0 rows affected (0.01 sec)

mysql> SET PERSIST log_error_services = 'log_filter_internal; log_sink_internal; log_sink_json; log_sink_syseventlog';
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like '%error_serv%';
+--------------------+-----------------------------------------------------------------------------+
| Variable_name      | Value                                                                       |
+--------------------+-----------------------------------------------------------------------------+
| log_error_services | log_filter_internal; log_sink_internal; log_sink_json; log_sink_syseventlog |
+--------------------+-----------------------------------------------------------------------------+
1 row in set (0.00 sec) 

Diese Einstellung bewirkt nun, dass die Daten an drei Stellen geschrieben werden:

1. Im klassischen Error-Log
2. Im JSON-Format
3. Im System-Eventlog des Betriebssystems (da gab es auch schon vorher; mysqld_safe —syslog ;-) ) 

bash ls -la *erro* 
-rw-r----- 1 root root 2092613 1. Apr 14:33 error.log 
-rw-r----- 1 root root 1028 1. Apr 14:33 error.log.00.json

bash> cat error.log.00.json
{ "prio" : 2, "err_code" : 13360, "component" : "plugin:sha256_password", "subsystem" : "Server", "source_file" : "sql_authentication.cc", "function" : "sha256_password_authenticate", "msg" : "Plugin sha256_password reported: ''sha256_password' is deprecated and will be removed in a future release. Please use caching_sha2_password instead'", "time" : "2021-04-01T12:33:53.517236Z", "ts" : 1617280433517, "thread" : 219556, "err_symbol" : "ER_SERVER_WARN_DEPRECATED", "SQL_state" : "HY000", "label" : "Warning" }
…

bash> tail -f /var/log/messages | grep mysqld
Apr  1 14:33:53 localhost mysqld[5496]: Plugin sha256_password reported: ''sha256_password' is deprecated and will be removed in a future release. Please use caching_sha2_password instead'
… 

Auch für den „Fehler-Filter" gibt es eine alternative Erweiterung (Plugin): „log_filter_dragnet"

Hierbei handelt es sich um einen regelbasierten Filter (z.B: mit IF-THEN-ELSE Strukturen), über den komplexere Mechanismen abgebildet werden können. Die genaue Funktionsweise inkl. der Syntax und einige Beispiel ist unter der folgenden URL zu finden: https://dev.mysql.com/doc/refman/8.0/en/error-log-rule-based-filtering.html

Lektion gelernt? 

Es ist erfreulich zu sehen, dass auch abseits der großen Features (InnoDB-Cluster, MySQL Shell,….) im Detail Optimierungen vorgenommen werden. Eine „detailliertes" Fehlermanagement ist sicherlich kein „Fehler" (!) und hilft dem einen oder anderen DBA die Betriebsprozesse zu optimieren.