MariaDB SQL Error Log Plugin: „Der größte Fehler ist, wenn man sich keines Fehlers bewusst ist.“ (Peter Tremayne)

Das MariaDB SQL Error Log Plugin kann ein gutes Werkzeug sein, um fehlerhafte Statements von Anwendern zu identifizieren. Häufig kommt es z.B. nach dem Update oder Patchen von Applikationen vor, dass sich Fehler (z.B: syntaktisch inkorrekte SQL-Statements) eingeschlichen haben. Genau an dieser Stelle lohnt es sich, dieses Plugin einmal genauer anzuschauen. 

Der Weise lernt aus den Fehlern anderer… (Konfuzius)

Die Aufgabe des SQL Error Log Plugins ist es nicht, Fehler der Datenbank (z.B. Speicherplatzprobleme) zu protokollieren. Für diese Aufgabe ist das Error-Log zuständig.

Die Aufgabe liegt darin, die Fehler der anderen (der Datenbank-User) zu protokollieren. Um mit der Aufzeichnung zu beginnen, muss das Plugin installiert und aktiviert werden:

MariaDB [(none)]> install soname 'sql_errlog';
Query OK, 0 rows affected (0.002 sec)

MariaDB [(none)]> show variables like 'sql_err%';
+--------------------------+----------------+
| Variable_name            | Value          |
+--------------------------+----------------+
| sql_error_log_filename   | sql_errors.log |
| sql_error_log_rate       | 1              |
| sql_error_log_rotate     | OFF            |
| sql_error_log_rotations  | 9              |
| sql_error_log_size_limit | 1000000        |
+--------------------------+----------------+ 

Fehler bekennen, hilft Fehler erkennen. (Manfred Heinrich)

Ab diesem Moment werden sämtliche an Anwender (User/Clients) verschickte Fehlercodes in ein separates Logfile (sql_error_log_filename) geschrieben.

Um ein paar Fehler zu „produzieren", legen wir eine Datenbank „prod" an und arbeiten ein wenig mit dieser:

MariaDB [(none)]> create database prod;
Query OK, 1 row affected (0.001 sec)


MariaDB [(none)]> create table prod.daten ( nr int primary key auto_increment, datum timestamp, wert varchar(20) not null);
Query OK, 0 rows affected (0.017 sec)


MariaDB [(none)]> use PROD;
ERROR 1049 (42000): Unknown database 'PROD'


MariaDB [(none)]> use prod;
Database changed


MariaDB [prod]> select * from DATEN;
ERROR 1146 (42S02): Table 'prod.DATEN' doesn't exist


MariaDB [prod]> insert into daten values (null, null, 'Wert 1');
Query OK, 1 row affected (0.005 sec)


MariaDB [prod]> insert into daten values (1, now(), 'Wert 2');
ERROR 1062 (23000): Duplicate entry '1' for key 'PRIMARY'


MariaDB [prod]> insert into daten values (2, now(), 'Wert 2');
Query OK, 1 row affected (0.007 sec)


MariaDB [prod]> insert into daten values (3, now(), NULL);
ERROR 1048 (23000): Column 'wert' cannot be null 

All die oben entstandenen Fehler wurden über das Plugin geloggt. Zusätzlich zum Fehlercode und dem fehlerhaften Statement werden die Uhrzeit und der User (inkl. des Hosts) protokolliert.

bash> tail -f sql_errors.log
2020-07-15 12:28:50 root[root] @ localhost [] ERROR 1049: Unknown database 'PROD' : (null)
2020-07-15 12:29:02 root[root] @ localhost [] ERROR 1146: Table 'prod.DATEN' doesn't exist : select * from DATEN
2020-07-15 12:29:38 root[root] @ localhost [] ERROR 1062: Duplicate entry '1' for key 'PRIMARY' : insert into daten values (1, now(), 'Wert 2')
2020-07-15 12:29:53 root[root] @ localhost [] ERROR 1048: Column 'wert' cannot be null : insert into daten values (3, now(), NULL)
 

Ordnung ist Unordnung höherer Ordnung (Kersten Kämpfer)

Wie bei jedem anderen Logfile sollte ein House-Keeping implementiert werden. Standardmäßig können die Dateien eine Größe von ca. 1 MB (sql_error_log_size_limit) erreichen. Beim Überschreiten dieses Schwellwertes werden sie rotiert. Im Normalfall (default) werden die letzten neun Logdateien archiviert (sql_error_log_rotations).

Bei Bedarf kann eine Rotation vorher erzwungen werden. Dazu wird die etwas irreführende Variable „sql_error_log_rotate" verwendet. Anders als der Name suggeriert, definiert diese nicht, ob Logdateien rotiert werden sollen, sondern durch die Zuweisung des Wertes „TRUE" wird der Vorgang vorzeitig erzwungen.

bash> ls -ltr sql_errors.log*
-rw-rw---- 1 mysql mysql 479 Jul 15 12:29 sql_errors.log.1
-rw-rw---- 1 mysql mysql   0 Jul 15 12:40 sql_errors.log

bash> mysql -uroot -proot --execute="set global sql_error_log_rotate=TRUE;"
bash> ls -ltr sql_errors.log*
-rw-rw---- 1 mysql mysql 479 Jul 15 12:29 sql_errors.log.2
-rw-rw---- 1 mysql mysql   0 Jul 15 12:40 sql_errors.log.1
-rw-rw---- 1 mysql mysql   0 Jul 15 12:41 sql_errors.log 

Über den Parameter „sql_error_log_rate" wird die Anzahl der protokollierten Fehler reduziert. Ein Wert von 100 bedeutet, dass nur jeder 100ste Fehler gespeichert wird. Ein Wert von 0 schaltet das Plugin inaktiv.

Fazit: Lernen, lernen und nochmals lernen... (Wladimir Iljitsch Lenin)

Das SQL Error Log ist eine nützliche Funktion, die dazu beitragen kann, Applikationsprobleme (schneller) zu erkennen. Diese Informationen sollten interessierten Entwicklern und Applikationsverantwortlichen zur Verfügung gestellt werden. Zusätzlich lohnt es, sich Gedanken darüber zu machen, wie eine Überwachung des Logfiles in das Monitoringkonzept integriert werden kann. So kann z.B. das Wachstum des Logs (in Bytes oder Zeilen) in Relation zur Zeit eine Auskunft darüber geben, ob es z.B. nach dem Patchen (oder anderen Aktivitäten auf Seiten der Applikation) zu mehr Fehlern auf der Datenbank kommt. Dies kommt sicher einem stabilen Betrieb der gesamten Anwendung zu Gute.