Mysql error log level

В MySQL на данный момент существуют 4 вида журнала (лога) и при достаточно серьёзной работе с базами на MySQL необходимо за ними следить. Например, бинарный лог у нас за сутки набирает около гигабайта, а размер жёсткого диска на сервере ограничен и за ними надо следить. Однако следить следует не только за бинарным логом, так как логи (журналы) в MySQL могут принести немалую пользу.

Итак, какие логи ведёт MySQL? Это:
1. бинарный лог (binary log)
2. лог ошибок (error log)
3. лог медленный запросов (slow query log)
4. лог запросов (general query log)
5. лог репликаций (relay log)

Каждый из них по-своему полезен.

Бинарный лог

В первую очередь полезен с точки зрения репликаций. Можно его бэкапить, можно использовать для восстановления данных на более точное время при использовании бэкапов. Лог содержит все команды изменений базы данных, выборки (select, show) не сохраняет, для таблиц, поддерживающих транзакции (BDB, InnoDB) запись в лог выполняется только после выполнения команды COMMIT. Для лога можно указывать список баз данных, которые надо логировать и список баз данных, которые не надо логировать. В более ранних версиях вместо бинарного лога использовался лог обновлений. Использование бинарного лога снижает производительность базы данных, однако его польза настолько велика, что крайне не рекомендуется его отключать. Рекомендуется защищать бинарный лог паролем, так как он может данные также о паролях пользователей. При достижении максимально разрешённого размера (1 гиг по умолчанию) создаётся следующий файл. Каждый новый файл имеет порядковый номер после имени.

Содержание бинарного лога можно посмотреть с помощью утилиты mysqlbinlog.

Основные настройки в my.cnf

Местоположение лога:
log_bin = /var/log/mysql/mysql-bin.log

Максимальный размер, минимум 4096 байт, по умолчанию 1073741824 байт (1 гигабайт):
max_binlog_size= 500M

Сколько дней хранится:
expire_logs_days = 3

Наиболее часто использующиеся команды

Повторение действий после операции восстановления:
shell> mysqlbinlog log_file | mysql -h server_name

Удаление логов до определённого файла:
PURGE BINARY LOGS TO 'mysql-bin.000';

Удаление логов до определённой даты:
PURGE BINARY LOGS BEFORE 'YYYY-MM-DD hh:mm:ss';

Лог ошибок

Особенно полезен в случаях сбоев. Лог содержит информацию об остановках, запусках сервера, а также сообщения о критических ошибках. Может содержать сообщения с предупреждениями (warnings).

Основные настройки в my.cnf

Местоположение лога:
log_error = /var/log/mysql/mysql.err

Флаг, указывающий стоит ли записывать в лог в том числе предупреждения (записываются, если значение больше нуля):
log_warnings = 1

Наиболее часто использующиеся команды

Переход к новому файл лога:
shell> mysqladmin flush-logs

Копирование старой части лога (необходимо, так как в случае повторного выполнения fluch он будет удалён):
shell> mv host_name.err-old backup-directory

Лог медленных запросов

Если есть подозрение, что приложение работает медленно из-за неэффективных запросов к базе, то в первую очередь следует проверить лог медленных запросов. В случае оптимизации запросов этот лог поможет выяснить, что необходимо оптимизировать в первую очередь.

Основные настройки в my.cnf

Местоположение лога:
log_slow_queries = /var/log/mysql/mysql_slow.log

Со скольки секунд выполнения запрос считается медленным, минимальное значений — 1 секунда, по умолчанию 10 секунд:
long_query_time = 10

Если надо логировать запросы, которые не используют индексы, надо добавить строку:
log-queries-not-using-indexes

Если надо вести лог медленных команд, таких как OPTIMIZE TABLE, ANALYZE TABLE и ALTER TABLE:
log-slow-admin-statements

Лог запросов

Лог содержит информацию о подключениях и отключениях клиентов, а также все SQL запросы, которые были получены. Фактически, это временный лог. Обычно лог удаляется автоматически сразу после выполнения всех команд (т.е. как только он стал ненужным). Лог ведётся в соответствии с очередность поступления запросов. Этот лог содержит все запросы к базе данных (независимо от приложений и пользователей). Так что если есть желание (или необходимость) проанализировать, какие необходимы индексы, какие запросы могли бы оптимизированы, то этот лог как раз может помочь в таких целях. Лог полезен не только для случаев, когда необходимо знать, какие запросы выполняются с базой данных, но и в случаях, когда ясно, что возникла ошибка с базой данных, но неизвестно, какой запрос был отправлен к базе данных (например, в случае генерации динамического SQL-а). Рекомендуется защищать лог запросов паролем, так как он может данные также о паролях пользователей.

Основные настройки в my.cnf

Местоположение лога:
log = /var/log/mysql/mysql.log

Наиболее часто использующиеся команды

В отличии от других логов, перезагрузка сервера и команда fluch не инициирует создание нового лога. Но это можно сделать вручную:
shell> mv host_name.log host_name-old.log
shell> mysqladmin flush-logs
shell> mv host_name-old.log backup-directory


Лог репликаций

Здесь логируются изменения, выполненные по инициации сервера репликаций. Как и бинарный лог, состоит из файлов, каждый из которых пронумерован.

Основные настройки в my.cnf

Местоположение лога:
relay-log = /var/log/mysql/mysql-relay-bin.log

Максимальный размер:
max_relay_log_size = 500М

Наиболее часто использующиеся команды

Начать новый файл лога можно только при остановленном дополнительном (slave) сервере:
shell> cat new_relay_log_name.index >> old_relay_log_name.index
shell> mv old_relay_log_name.index new_relay_log_name.index

Команда fluch logs инициирует ротацию лога.

This tutorial shows you how to configure and view different MySQL logs. MySQL is
an open-source relational database based on SQL (Structured Query Language).
MySQL offers various built-in logs. In general, a database is the cornerstone of
almost every backend, and because of that administrators want to log this
service.

MySQL has multiple logs with different purpose. We will focus on following four
logs:

• Error log: Records problems encountered starting, running, or stopping
  mysqld. This log is stored by default in the /var/log directory. It could
  be useful if you want to analyze the server itself.
• General query logs: Records every connection established with each client.
  This log records everything that client sent to the server. This log is useful
  to determine client problems.
• Binary logs: Record each event that manipulates data in the database.
  These log records operations such as a table creating, modification of schema,
  inserting new values, or querying tables. These logs are used to backup and
  recover the database.
• Slow query log: Record of each query, which execution took too much time.
  This log could be useful for the optimisation of slow SQL queries.

In this tutorial, you will do the following actions:

• You will install the MySQL server and view default error log.
• You will connect to MySQL server, view metadata about general query logs
  and view these logs.
• You will understand the concept of the MySQL binary logs and where to find
  them.
• You will enable and configure a slow query log, simulate some slow query
  and check this incident in the new log.

Prerequisites

You will need:

• Ubuntu 20.04 distribution including the non-root user with sudo access.
• Basic knowledge of SQL languages (understanding of simple select query
  statement).

Step 1 — Viewing Error Log

The MySQL server is maintained by the command-line program mysqld. This
program manages access to the MySQL data directory that contains databases and
tables. The problems encountered during mysqld starting, running, or stopping
are stored as a custom log in the directory /var/log/mysql. This log doesn’t
include any information about SQL queries. It is useful for the analysis of the
MySQL server.

First of all, let’s install the MySQL server. Ubuntu 20.04 allows to install the
MySQL from default packages with the apt install (installation requires sudo
privilege):

$ sudo apt update
$ sudo apt install mysql-server

The first command will update Ubuntu repositories, and the second will download
and install required packages for the MySQL server.

Now, the server is installed. The new service already creates a default error
log. You can list the directory /var/log and find a new subdirectory mysql
with ls:

You’ll see the program’s output appear on the screen:

Output
alternatives.log       bootstrap.log           kern.log.4.gz
alternatives.log.1     btmp                    lastlog
alternatives.log.2.gz  btmp.1                  letsencrypt
alternatives.log.3.gz  cups                    my-custom-app
apache2                dist-upgrade            mysql
apport.log             dmesg                   openvpn
apport.log.1           dmesg.0                 private
apport.log.2.gz        dmesg.1.gz              speech-dispatcher
apport.log.3.gz        dmesg.2.gz              syslog
apport.log.4.gz        dmesg.3.gz              syslog.1
apport.log.5.gz        dmesg.4.gz              syslog.2.gz
apport.log.6.gz        dpkg.log                syslog.3.gz
apport.log.7.gz        dpkg.log.1              syslog.4.gz
apt                    dpkg.log.2.gz           syslog.5.gz
auth.log               dpkg.log.3.gz           syslog.6.gz
auth.log.1             faillog                 syslog.7.gz
auth.log.2.gz          fontconfig.log          teamviewer15
auth.log.3.gz          gdm3                    test.log
auth.log.4.gz          gpu-manager.log         ubuntu-advantage.log
boot.log               gpu-manager-switch.log  unattended-upgrades
boot.log.1             hp                      wtmp
boot.log.2             installer               wtmp.1
boot.log.3             journal                 Xorg.0.log
boot.log.4             kern.log                Xorg.0.log.old
boot.log.5             kern.log.1              Xorg.1.log
boot.log.6             kern.log.2.gz           Xorg.1.log.old
boot.log.7             kern.log.3.gz

The output shows also directory mysql. This directory contains by default
single log error.log. Let’s view the content of file error.log with cat:

cat /var/log/mysql/error.log

You’ll see the program’s output appear on the screen:

Output
2021-04-28T09:36:19.040254Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.23-0ubuntu0.20.04.1) initializing of server in progress as process 62373
2021-04-28T09:36:19.046865Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-04-28T09:36:20.482915Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-04-28T09:36:23.709432Z 6 [Warning] [MY-010453] [Server] [email protected] is created with an empty password ! Please consider switching off the --initialize-insecure option.
2021-04-28T09:36:28.971810Z 6 [System] [MY-013172] [Server] Received SHUTDOWN from user boot. Shutting down mysqld (Version: 8.0.23-0ubuntu0.20.04.1).
2021-04-28T09:36:33.851492Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.23-0ubuntu0.20.04.1) starting as process 62437
2021-04-28T09:36:33.870257Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-04-28T09:36:34.114770Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-04-28T09:36:34.222753Z 0 [ERROR] [MY-011292] [Server] Plugin mysqlx reported: 'Preparation of I/O interfaces failed, X Protocol won't be accessible'
2021-04-28T09:36:34.222924Z 0 [ERROR] [MY-011300] [Server] Plugin mysqlx reported: 'Setup of socket: '/var/run/mysqld/mysqlx.sock' failed, can't create lock file /var/run/mysqld/mysqlx.sock.lock'
2021-04-28T09:36:34.354295Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-04-28T09:36:34.354479Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
...

The output shows that the file stores plain text records about the mysqld
server initialisation, and running.

Step 2 — Viewing General Query Logs

The server writes records about each client event during connection to the
general query log. Basically, it keeps the information about all SQL statements
that happens. This log is useful when the administrators want to know what
clients exactly execute.

Connecting to Server and Checking General Query Log Status

First of all, let’s check the status of the general query log because this
logging feature can be turned off.

You can connect to MySQL server as a root client:

You will be redirected to MySQL command-line.

Now, you can view system variables related to the general query log by executing
command show variables:

mysql> show variables like '%general%';

The clause specifies a pattern that should match the variable. In our case, the
pattern '%general%' specifies to show variables that contain the string
general. You’ll see the program’s output appear on the screen:

Output
+------------------+-----------------------------+
| Variable_name    | Value                       |
+------------------+-----------------------------+
| general_log      | ON                          |
| general_log_file | /var/lib/mysql/alice.log    |
+------------------+-----------------------------+
2 rows in set (0.01 sec)

The output shows two variables:

• general_log: the variable holds value ON (general log enable), or OFF
  (general log disabled).
• general_log_file: the variable defines where is the log stored in the file
  system.

As you can see, the general query log is by default enabled. We can disconnect
from the server by executing the exit command:

You will be redirected back to the terminal.

Viewing General Query Log

Now, you can view the content of this log with a cat (the sudo is required
because this file is maintained by the system):

$ sudo cat /var/lib/mysql/alice.log

You’ll see the program’s output appear on the screen:

Output
/usr/sbin/mysqld, Version: 8.0.23-0ubuntu0.20.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
2021-04-28T10:47:28.713271Z    10 Connect   [email protected] on  using Socket
2021-04-28T10:47:28.713625Z    10 Query select @@version_comment limit 1
2021-04-28T10:53:50.778598Z    10 Query show variables like '%general%'
2021-04-28T13:35:41.944309Z    10 Quit

The output shows all statement executed on the server. You can see the time
stamp and the specific command that was executed. There is also the executed
command show variables like '%general%'.

Step 3 — Listing Binary Logs

The binary log contains events that manipulated the database. If you want to
recover the database, you need a backup and a binary log relevant to this
backup. There are multiple binary logs because they are versioned.

By default, the binary logs are enabled. You can check where are they stored.
Let’s connect to the MySQL server as a root client:

You will be redirected to MySQL prompt.

Now, you can check the binary logs status by executing show binary logs:

The command will list the binary log files on the server:

Output
+---------------+-----------+-----------+
| Log_name      | File_size | Encrypted |
+---------------+-----------+-----------+
| binlog.000001 |       179 | No        |
| binlog.000002 |       403 | No        |
| binlog.000003 |       770 | No        |
| binlog.000004 |       179 | No        |
| binlog.000005 |       403 | No        |
| binlog.000006 |       892 | No        |
+---------------+-----------+-----------+
6 rows in set (0.00 sec)

The output shows all binary logs. Now, we can find out where are this logs
stored.

We can show logs location by executing command show variables:

mysql> show variables like '%log_bin%';

We already use this show clause in the previous step. This time, the clause
shows variables that contain the string log_bin. You’ll see the program’s
output appear on the screen:

Output
+---------------------------------+-----------------------------+
| Variable_name                   | Value                       |
+---------------------------------+-----------------------------+
| log_bin                         | ON                          |
| log_bin_basename                | /var/lib/mysql/binlog       |
| log_bin_index                   | /var/lib/mysql/binlog.index |
| log_bin_trust_function_creators | OFF                         |
| log_bin_use_v1_row_events       | OFF                         |
| sql_log_bin                     | ON                          |
+---------------------------------+-----------------------------+
6 rows in set (0.00 sec)

The output shows that the binary logs are stored in directory /var/lib/mysql,
and they are labelled as binlog.index (for example binlog.000001).

We can disconnect from the server by executing the exit command:

You will be redirected back to the terminal.

Now, let’s list the directory /var/lib/mysql but only as a root because it is
owned and maintained by the system:

You’ll see the program’s output appear on the screen:

Output
auto.cnf         ca.pem                 ib_logfile0    private_key.pem
binlog.000001    client-cert.pem      ib_logfile1      public_key.pem
binlog.000002    client-key.pem       ibtmp1             server-cert.pem
binlog.000003    debian-5.7.flag      '#innodb_temp' server-key.pem
binlog.000004    EXAMPLE_DB           alice.log      sys
binlog.000005    '#ib_16384_0.dblwr'  alice.pid      undo_001
binlog.000006    '#ib_16384_1.dblwr'  mysql            undo_002
binlog.index     ib_buffer_pool       mysql.ibd
ca-key.pem     ibdata1              performance_schema

The output shows that the directory /var/lib/mysql contains the binary log
files.

Step 4 — Configuring Slow Query Log

MySQL allows to log queries, which took too much time. This mechanism is called
a slow query log.

Enabling Slow Query Logging

By default, the slow query log is disabled. You can enable it by editing MySQL
configuration file /etc/mysql/mysql.conf.d/mysqld.cnf (sudo required):

$ sudo nano /etc/mysql/mysql.conf.d/mysqld.cnf

The file contains following lines that holds configuration variables (by default
commented out):

...
# Here you can see queries with especially long duration
# slow_query_log          = 1
# slow_query_log_file     = /var/log/mysql/mysql-slow.log
# long_query_time = 10
...

These three lines holds following three configuration variables:

• slow_query_log: the slow query logging is disable (value 0) or enabled
  (value 1).
• slow_query_log_file: the slow query log is stored in the file
  /var/log/mysql/mysql-slow.log. You can specify your own file.
• long_query_time: by default, the slow query logs record each SQL query that
  takes more than 10 seconds. You can change this minimal time interval to
  another value. The value can be specified as a floating-point number where the
  value 1.0 refers to 1 second.

You can enable slow query log by uncommenting this three lines. Also, you can
set your own long_query_time value:

...
# Here you can see queries with especially long duration
slow_query_log          = 1
slow_query_log_file     = /var/log/mysql/mysql-slow.log
long_query_time = 5
...

In our example, we change the default long_query_time value to 5 seconds. Now,
you can save the file.

If you want immediately apply the new configuration rules then you must restart
the MySQL server with systemctl (sudo required):

$ sudo systemctl restart mysql.service

Now, the MySQL server enables slow query log.

Checking Slow Query Log Status

You can check that the log is enabled if you login into the MySQL server as a
root client:

You will be redirected to MySQL prompt.

Let’s check the slow query log status by executing command show variables:

mysql> show variables like '%slow_query_log%';

Once again, we use the show clause. This time, the clause shows variables that
contain the string slow_query_log. You’ll see the program’s output appear on
the screen:

Output
+---------------------+----------------------------------+
| Variable_name       | Value                            |
+---------------------+----------------------------------+
| slow_query_log      | ON                               |
| slow_query_log_file | /var/log/mysql/mysql-slow.log   |
+---------------------+----------------------------------+
2 rows in set (0.00 sec)

The output shows that the slow query log is enabled (the variable
slow_query_log holds the value ON). The log is stored in the file
/var/log/mysql/mysql-slow.log. You can see that it is the same file as the
file specified in the configuration script.

Let’s view actual slow query time interval by executing the command
show variables:

mysql> show variables like '%long_query_time%';

You’ll see the program’s output appear on the screen:

Output
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time |  5.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

The output shows that the variable long_query_time holds the value 5 seconds
(as we define in the configuration script).

Viewing Slow Query Log

At last, we can check that the MySQL records slow queries to the new log. You
can execute the following select query that takes 6 seconds:

The select will wait 6 seconds and then return 0:

Output
+----------+
| sleep(6) |
+----------+
|        0 |
+----------+
1 row in set (6.01 sec)

The output shows that this query takes 6 seconds. As a result, it should be
recorded in a slow query log.

We can disconnect from the server by executing the exit command:

You will be redirected back to the terminal.

At last, we can print content of the slow query log
/var/log/mysql/mysql-slow.log (the sudo is required because the file is
maintained by system):

$ sudo cat /var/log/mysql/mysql-slow.log

You’ll see the program’s output appear on the screen:

/usr/sbin/mysqld, Version: 8.0.23-0ubuntu0.20.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2021-04-29T06:28:55.445053Z
# [email protected]: root[root] @ localhost []  Id:    15
# Query_time: 6.000443  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1619677729;
select sleep(6);

You can see that the output shows record about execution query
select sleep(6).

Conclusion

In this tutorial, you configured and viewed different MySQL logs. You installed
the MySQL server and viewed the error log. You connected to the server,
viewed the general query logs and their configuration. You listed binary
logs. At last, you enabled, configured and viewed a slow query log.

Next article

→

We are yet to see a software that runs perfectly, without any issues. MySQL is no exception there. It’s not the software’s fault – we need to be clear about that. We use MySQL in different places, on different hardware and within different environments. It’s also highly configurable. All those features make it great product but they come with a price – sometimes some settings won’t work correctly under certain conditions. It is also pretty easy to make simple human mistakes like typos in the MySQL configuration. Luckily, MySQL provides us with means to understand what is wrong through the error log. In this blog, we’ll see how to read the information in the error log.

This is the fifteenth installment in the ‘Become a MySQL DBA’ blog series. Our previous posts in the DBA series include:

• Optimizing Hints for faster queries,
• Using EXPLAIN to improve SQL Queries,
• Database Indexing,
• Deep Dive pt-query-digest,
• Analyzing SQL Workload with pt-query-digest,
• Query Tuning Process,
• Configuration Tuning,
• Live Migration using MySQL Replication,
• Database Upgrades,
• Replication Topology Changes,
• Schema Changes,
• High Availability,
• Backup & Restore,
• Monitoring & Trending.

Error log on MySQL – clean startup and shutdown

MySQL’s error log may contain a lot of information about different issues you may encounter. Let’s start with checking what a ‘clean’ start of MySQL looks like. It will make it easier to find any anomalies later.

At first, all plugins (and storage engines, which do work as plugins in MySQL 5.6) are initiated. If something is not right, you’ll see errors on this stage.

2015-10-26 19:35:20 13762 [Note] Plugin 'FEDERATED' is disabled.

Next we can see a significant part related to InnoDB initialization.

2015-10-26 19:35:20 13762 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-26 19:35:20 13762 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-26 19:35:20 13762 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-26 19:35:20 13762 [Note] InnoDB: Memory barrier is not used
2015-10-26 19:35:20 13762 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-26 19:35:20 13762 [Note] InnoDB: Using Linux native AIO
2015-10-26 19:35:20 13762 [Note] InnoDB: Using CPU crc32 instructions
2015-10-26 19:35:20 13762 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-26 19:35:21 13762 [Note] InnoDB: Completed initialization of buffer pool
2015-10-26 19:35:21 13762 [Note] InnoDB: Highest supported file format is Barracuda.
2015-10-26 19:35:21 13762 [Note] InnoDB: 128 rollback segment(s) are active.
2015-10-26 19:35:21 13762 [Note] InnoDB: Waiting for purge to start
2015-10-26 19:35:21 13762 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 710963181

In the next phase, authentication plugins are initiated (if they are configured correctly).

2015-10-26 19:35:21 13762 [Note] RSA private key file not found: /var/lib/mysql//private_key.pem. Some authentication plugins will not work.
2015-10-26 19:35:21 13762 [Note] RSA public key file not found: /var/lib/mysql//public_key.pem. Some authentication plugins will not work.

At the end you’ll see information about binding MySQL to the configured IP and port. Event scheduler is also initialized. Finally, you’ll see ‘ready for connections’ message indicating that MySQL started correctly.

2015-10-26 19:35:21 13762 [Note] Server hostname (bind-address): '*'; port: 33306
2015-10-26 19:35:21 13762 [Note] IPv6 is available.
2015-10-26 19:35:21 13762 [Note]   - '::' resolves to '::';
2015-10-26 19:35:21 13762 [Note] Server socket created on IP: '::'.
2015-10-26 19:35:21 13762 [Warning] 'proxies_priv' entry '@ [email protected]' ignored in --skip-name-resolve mode.
2015-10-26 19:35:21 13762 [Note] Event Scheduler: Loaded 2 events
2015-10-26 19:35:21 13762 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.26-74.0'  socket: '/var/run/mysqld/mysqld.sock'  port: 33306  Percona Server (GPL), Release 74.0, Revision 32f8dfd

How does the shutdown process look like? Let’s follow it step by step:

2015-10-26 19:35:13 12955 [Note] /usr/sbin/mysqld: Normal shutdown

This line is very important – MySQL can be stopped in many ways – a user can use init scripts, it’s possible to use ‘mysqladmin’ to execute SHUTDOWN command, it’s also possible to send a SIGTERM to MySQL initiating shutdown of the database. At times you’ll be investigating why MySQL instance had stopped – this line is always an indication that someone (or something) triggered clean shutdown. No crash happened, MySQL wasn’t killed either.

2015-10-26 19:35:13 12955 [Note] Giving 12 client threads a chance to die gracefully
2015-10-26 19:35:13 12955 [Note] Event Scheduler: Purging the queue. 2 events
2015-10-26 19:35:13 12955 [Note] Shutting down slave threads
2015-10-26 19:35:15 12955 [Note] Forcefully disconnecting 6 remaining clients
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 37  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 53  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 38  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 39  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 44  user: 'cmon'
2015-10-26 19:35:15 12955 [Warning] /usr/sbin/mysqld: Forcing close of thread 47  user: 'cmon'

In the above, MySQL is closing remaining connections – it allows them to finish on their own but if they do not close, they will be forcefully terminated.

2015-10-26 19:35:15 12955 [Note] Binlog end
2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'partition'
2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'ARCHIVE'
...

Here MySQL is shutting down all plugins that were enabled in its configuration. There are many of them so we removed some output for the sake of better visibility.

2015-10-26 19:35:15 12955 [Note] Shutting down plugin 'InnoDB'
2015-10-26 19:35:15 12955 [Note] InnoDB: FTS optimize thread exiting.
2015-10-26 19:35:15 12955 [Note] InnoDB: Starting shutdown...
2015-10-26 19:35:17 12955 [Note] InnoDB: Shutdown completed; log sequence number 710963181

One of them is InnoDB – this step may take a while as a clean InnoDB shutdown can take some time on a busy server, even with InnoDB fast shutdown enabled (and this is the default setting).

2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MyISAM'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MRG_MYISAM'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'CSV'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'MEMORY'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'sha256_password'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'mysql_old_password'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'mysql_native_password'
2015-10-26 19:35:17 12955 [Note] Shutting down plugin 'binlog'
2015-10-26 19:35:17 12955 [Note] /usr/sbin/mysqld: Shutdown complete

The shutdown process concludes with ‘Shutdown complete’ message.

Configuration errors

Let’s start with a basic issue – configuration error. It’s really a popular problem. Sometimes we make a typo in a variable name, while editing my.cnf. MySQL parses its configuration files when it starts. If something is wrong, it will refuse to run. Let’s take a look at some examples:

2015-10-27 11:20:05 18858 [Note] Plugin 'FEDERATED' is disabled.
2015-10-27 11:20:05 18858 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:20:05 18858 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:20:05 18858 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:20:05 18858 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:20:05 18858 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:20:05 18858 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:20:05 18858 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:20:05 18858 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-27 11:20:05 18858 [Note] InnoDB: Completed initialization of buffer pool
2015-10-27 11:20:05 18858 [Note] InnoDB: Highest supported file format is Barracuda.
2015-10-27 11:20:05 18858 [Note] InnoDB: 128 rollback segment(s) are active.
2015-10-27 11:20:05 18858 [Note] InnoDB: Waiting for purge to start
2015-10-27 11:20:06 18858 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-74.0 started; log sequence number 773268083
2015-10-27 11:20:06 18858 [ERROR] /usr/sbin/mysqld: unknown variable '--max-connections=512'
2015-10-27 11:20:06 18858 [ERROR] Aborting

As you can see from the above, we have here a clear copy-paste error with regards to max_connections variable. MySQL doesn’t accept ‘–’ prefix in my.cnf so if you are copying settings from the ‘ps’ output or from MySQL documentation, please keep it in mind. There are many things that can go wrong but it’s important that ‘unknown variable’ error always points you to my.cnf and to some kind of mistake which MySQL can’t understand.

Another problem can be related to misconfigurations. Let’s say we over-allocated memory on our server. Here’s what you might see:

2015-10-27 11:24:41 31325 [Note] Plugin 'FEDERATED' is disabled.
2015-10-27 11:24:41 31325 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:24:41 31325 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:24:41 31325 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:24:41 31325 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:24:41 31325 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:24:41 31325 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:24:41 31325 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:24:41 31325 [Note] InnoDB: Initializing buffer pool, size = 512.0G
InnoDB: mmap(70330089472 bytes) failed; errno 12
2015-10-27 11:24:41 31325 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
2015-10-27 11:24:41 31325 [ERROR] Plugin 'InnoDB' init function returned error.
2015-10-27 11:24:41 31325 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-10-27 11:24:41 31325 [ERROR] Unknown/unsupported storage engine: InnoDB
2015-10-27 11:24:41 31325 [ERROR] Aborting

As you can clearly see, we’ve tried to allocate 512G of memory which was not possible on this host. InnoDB is required for MySQL to start, therefore error in initializing InnoDB prevented MySQL from starting.

Permission errors

Below are three examples of three crashes related to permission errors.

/usr/sbin/mysqld: File './binlog.index' not found (Errcode: 13 - Permission denied)
2015-10-27 11:31:40 11469 [ERROR] Aborting

This one is pretty self-explanatory. As stated, MySQL couldn’t find an index file for binary logs due to ‘permission denied’ error. This is also a hard stop for MySQL, it has to be able to read and write to binary logs.

2015-10-27 11:32:46 13601 [Note] Plugin 'FEDERATED' is disabled.
2015-10-27 11:32:46 13601 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:32:46 13601 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:32:46 13601 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:32:46 13601 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:32:46 13601 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:32:46 13601 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:32:46 13601 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:32:46 13601 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-27 11:32:46 13601 [Note] InnoDB: Completed initialization of buffer pool
2015-10-27 11:32:46 13601 [ERROR] InnoDB: ./ibdata1 can't be opened in read-write mode
2015-10-27 11:32:46 13601 [ERROR] InnoDB: The system tablespace must be writable!
2015-10-27 11:32:46 13601 [ERROR] Plugin 'InnoDB' init function returned error.
2015-10-27 11:32:46 13601 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-10-27 11:32:46 13601 [ERROR] Unknown/unsupported storage engine: InnoDB
2015-10-27 11:32:46 13601 [ERROR] Aborting

The above is another permission issue, this time the problem is related to ibdata1 file – shared system tablespace which is used for InnoDB to store its internal data (InnoDB dictionary and, by default, undo logs). Even if you use innodb_file_per_table, which is a default setting in MySQL 5.6, InnoDB still requires this file so it can intialize.

2015-10-27 11:35:21 17826 [Note] Plugin 'FEDERATED' is disabled.
/usr/sbin/mysqld: Can't find file: './mysql/plugin.frm' (errno: 13 - Permission denied)
2015-10-27 11:35:21 17826 [ERROR] Can't open the mysql.plugin table. Please run mysql_upgrade to create it.
2015-10-27 11:35:21 17826 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-10-27 11:35:21 17826 [Note] InnoDB: The InnoDB memory heap is disabled
2015-10-27 11:35:21 17826 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-10-27 11:35:21 17826 [Note] InnoDB: Memory barrier is not used
2015-10-27 11:35:21 17826 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-10-27 11:35:21 17826 [Note] InnoDB: Using Linux native AIO
2015-10-27 11:35:21 17826 [Note] InnoDB: Using CPU crc32 instructions
2015-10-27 11:35:21 17826 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2015-10-27 11:35:21 17826 [Note] InnoDB: Completed initialization of buffer pool
2015-10-27 11:35:21 17826 [Note] InnoDB: Highest supported file format is Barracuda.
2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysql/innodb_index_stats'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Tablespace open failed for '"mysql"."innodb_index_stats"', ignored.
2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Could not find a valid tablespace file for 'mysql/innodb_table_stats'. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
2015-10-27 11:35:21 17826 [ERROR] InnoDB: Tablespace open failed for '"mysql"."innodb_table_stats"', ignored.
2015-10-27 11:35:21 7fa02e97d780  InnoDB: Operating system error number 13 in a file operation.
InnoDB: The error means mysqld does not have the access rights to
InnoDB: the directory.

Here we have an example of permission issues related to system schema (‘mysql’ schema). As you can see, InnoDB reported it does not have access rights to open tables in this schema. Again, this is serious problem which is a hard stop for MySQL.

Out of memory errors

Another set of frequent issues related to MySQL servers running out of memory. It can manifest in many different ways but the most popular is this one:

Killed
151027 12:18:58 mysqld_safe Number of processes running now: 0

mysqld_safe is an ‘angel’ process which monitors mysqld and restarts it when it dies. It’s true for MySQL but not for recent Galera nodes – in this case it won’t restart MySQL but you’ll see following sequence:

Killed
151027 12:18:58 mysqld_safe Number of processes running now: 0
151027 12:18:58 mysqld_safe WSREP: not restarting wsrep node automatically
151027 12:18:58 mysqld_safe mysqld from pid file /var/lib/mysql/mysql.pid ended

Another way memory issue may show up is through the following messages in the error log:

InnoDB: mmap(3145728 bytes) failed; errno 12
InnoDB: mmap(3145728 bytes) failed; errno 12

What’s important to keep in mind is that error codes can easily be checked using ‘perror’ utility. In this case, it makes perfectly clear what exactly happened:

$ perror 12
OS error code  12:  Cannot allocate memory

If you suspect a memory problem or we’d even say – if you are encountering unexpected MySQL crashes, you can also run dmesg to get some more data. If you see output like below, you can be certain that the problem was caused by OOM Killer terminating MySQL:

[ 4165.802544] Out of memory: Kill process 8143 (mysqld) score 938 or sacrifice child
[ 4165.808329] Killed process 8143 (mysqld) total-vm:5101492kB, anon-rss:3789388kB, file-rss:0kB
[ 4166.226410] init: mysql main process (8143) killed by KILL signal
[ 4166.226437] init: mysql main process ended, respawning

InnoDB crashes

InnoDB, most of the time, is a very solid and durable storage engine. Unfortunately, under some circumstances, data may become corrupted. Usually it’s related to either misconfiguration (for example, disabling double-write buffer) or some kind of faulty hardware (faulty memory modules, unstable I/O layer). In those cases it can happen that InnoDB will crash. Crashes can also be triggered by InnoDB bugs. It’s not common but it happens from time to time. No matter the reason of a crash, the error log usually looks in a similar way. Let’s go over a live example.

2015-10-13 15:08:06 7f53f0658700  InnoDB: Assertion failure in thread 139998492198656 in file btr0pcur.cc line 447
InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_block_get_page_no(btr_pcur_get_block(cursor))

InnoDB code is full of sanity checks – assertions are very frequent and, if one of them fails, InnoDB intentionally crashes MySQL. At the beginning you’ll see information about exact location of the assertion which failed. This gives you information about what exactly may have happened – MySQL source code is available on the internet and it’s pretty easy to download code related to your particular version. It may sounds scary but it’s not – MySQL code is properly documented and it’s not a problem to figure out at least what kind of activity triggers your issue.

InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.

InnoDB logging tries to be as helpful as possible – as you can see, there’s information about InnoDB recovery process. Under some circumstances it may allow you to start MySQL and dump the InnoDB data. It’s used as “almost a last resort” – one step further and you’ll end up digging in InnoDB files using hex editor.

13:08:06 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=67108864
read_buffer_size=131072
max_used_connections=36
max_threads=514
thread_count=27
connection_count=26
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 269997 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

In the next step you’ll see some of the status counters printed. It’s supposed to give you some idea about configuration – maybe you configured MySQL to use too much resources? Once you go over this data, we’ll reach the backtrace. This piece of information will guide you through the stack and show you what kind of calls were executed when crash happened. Let’s check what exactly happened in this particular case.

Thread pointer: 0xa985960
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f53f0657d40 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8cd37c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x6555a1]
/lib64/libpthread.so.0(+0xf710)[0x7f540f978710]
/lib64/libc.so.6(gsignal+0x35)[0x7f540dfd4625]
/lib64/libc.so.6(abort+0x175)[0x7f540dfd5e05]
/usr/sbin/mysqld[0xa0277b]
/usr/sbin/mysqld[0x567f88]
/usr/sbin/mysqld[0x99afde]
/usr/sbin/mysqld[0x8eb926]
/usr/sbin/mysqld(_ZN7handler11ha_rnd_nextEPh+0x5d)[0x59a6ed]
/usr/sbin/mysqld(_Z13rr_sequentialP11READ_RECORD+0x20)[0x800cd0]
/usr/sbin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyy+0xc88)[0x8128c8]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1bc5)[0x6d6d15]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5a8)[0x6dc228]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x108c)[0x6dda4c]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6ab002]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x6ab0f0]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xaddd73]
/lib64/libpthread.so.0(+0x79d1)[0x7f540f9709d1]
/lib64/libc.so.6(clone+0x6d)[0x7f540e08a8fd]

We can see that problem was triggered when MySQL was executing a DELETE command. Records were read sequentially and full table scan was performed (handler read_rnd_next). Combined with information from the beginning:

InnoDB: Failing assertion: btr_page_get_prev(next_page, mtr) == buf_block_get_page_no(btr_pcur_get_block(cursor))

we can tell the crash happened when InnoDB was performing a scan of the buffer pool (assertion was triggered in btr_pcur_move_to_next_page method).

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (a991d40): DELETE FROM cmon_stats WHERE cid = 2 AND ts < 1444482484
Connection ID (thread ID): 5
Status: NOT_KILLED

Finally, we can see (sometimes, it’s not always printed) which thread triggered the assertion. In our case we can confirm that indeed it was a DELETE query which caused some kind of problem.

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
151013 15:08:06 mysqld_safe Number of processes running now: 0

As we said, usually MySQL is pretty verbose when it comes to the error log. Sometimes, though, things go so wrong that MySQL can’t really collect much of the information. It still gives a pretty clear indication that something went very wrong (signal 11). Please take a look at the following real life example:

22:31:40 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=10
max_threads=202
thread_count=9
connection_count=7
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 113388 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x1fb7050
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
Segmentation fault (core dumped)
150119 23:48:08 mysqld_safe Number of processes running now: 0

As you can see, we have clear information that MySQL crashed. There’s no additional information, though. Segmentation faults can also be logged in diagnostic messages. In this particular case dmesg returned:

[370591.200799] mysqld[5462]: segfault at 51 ip 00007fe624e3e688 sp 00007fe4f4099c30 error 4 in libgcc_s.so.1[7fe624e2f000+16000]

It’s not much, as you can see, but such information can prove to be very useful if you decide to file a bug against the software provider, be it Oracle, MariaDB, Percona or Codership. It can also be helpful in finding relevant bugs already reported.

It’s not always possible to fix the problem based only on the information written in the error log. It’s definitely a good place to start debugging problems in your database, though. If you are hitting some kind of very common, simple misconfiguration, information you’d find in the error log should be enough to pinpoint a cause and find a solution. If we are talking about serious MySQL crashes, things are definitely different – most likely you won’t be able to fix the issue on your own (unless you are a developer familiar with MySQL code, that is) On the other hand, this data may be more than enough to identify the culprit and locate existing bug reports which cover it. Such bug reports contain lots of discussion and tips or workarounds – it’s likely that you’ll be able to implement one of them. Even information that the given bug was fixed in version x.y.z is useful – you’ll be able to verify it and, if it does solve your problem, to plan for upgrade. In the worst case scenario, you should have enough data to create a bug report on your own.

In the next post in the series, we are going to take a guided tour through the error log (and other logs) you may find in your Galera cluster. We’ll cover what kind of issues you may encounter and how to solve them.

MySQL error log contains diagnostics messages such as errors, warnings and notes that occur during MySQL startup, shutdown and while the server is running. For example, a InnoDB table is corrupted and need to repaired, This will be recorded in the error log. MySQL 8.0 Error uses the MySQL component architecture for log event filtering and writing. The MySQL system variable log_error_services controls which log components to enable and the rules for filtering the log events. The component table in the mysql system database contains the information about currently loaded comments and shows which components have been registered with INSTALL COMPONENT. To confirm the components installed, you may use the SQL below:

SELECT * FROM mysql.component;

Currently the available log components are in lib/plugins:

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

Error Log configuration / system variables

The log_error_services system variable controls which log components to enable for error logging

mysql> select @@log_error_services;
+----------------------------------------+
| @@log_error_services                   |
+----------------------------------------+
| log_filter_internal; log_sink_internal |
+----------------------------------------+
1 row in set (0.00 sec)

The default value indicates that log evens first pass through the built-in filter controller, log_filter_interval and later through the built-in log writer component, log_sink_interval. 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. The combination of  log_filter_internal and log_sink_internal implements the default error log filtering and output behavior.

The output destination of error log can be collected from system variable log_error .  You can configure the destination of error log either to the system log or JSON file.

You can make mysqld to write the error log to system log (Event Log on Windows and syslog on Linux and Unix systems):

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

You can enable JSON writer to record the error log by first loading the writer component and then modifying log_error_services system variable:

INSTALL COMPONENT 'file://component_log_sink_json';
SET GLOBAL log_error_services = 'log_filter_internal; log_sink_json';

traditional error log:

2019-03-10T08:36:59.950769Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.15) starting as process 13222
2019-03-10T08:37:00.253523Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2019-03-10T08:37:00.267812Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2019-03-10T08:37:00.429164Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/var/run/mysqld/mysqlx.sock' bind-address: '::' port: 33060
2019-03-10T08:37:37.635761Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.15)  MySQL Community Server - GPL.
2019-03-10T08:37:37.985380Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.15) starting as process 13410
2019-03-10T08:37:38.277912Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2019-03-10T08:37:38.291494Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.15'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.

JSON error log:

{ "prio" : 0, "err_code" : 10910, "source_line" : 2191, "source_file" : "mysqld.cc", "function" : "clean_up", "msg" : "/usr/sbin/mysqld: Shutdown complete (mysqld 8.0.15)  MySQL Community Server - GPL.", "time" : "2019-03-10T09:21:18.722864Z", "err_symbol" : "ER_SERVER_SHUTDOWN_COMPLETE", "SQL_state" : "HY000", "subsystem" : "Server", "label" : "System" }

• Filtering MySQL error with log_error_verbosity:
  • Errors only – 1
  • Errors and warnings  – 2
  • Errors, warnings and notes – 3
    • If log_error_verbosity is configured to 2 or higher, the MySQL server even logs the statement that are unsafe for statement-based logging / replication. if the value is 3, the server logs aborted connections and access-denied errors for fresh connection attempts. It is recommended to configure log_error_verbosity with 2 or higher to record detailed information about what is happening to MySQL infrastructure.
• How MySQL 8.0 component based error logging filters are different ? 

We are used to default built-in error log filters that are configured with MySQL system variable log_error_verbosity (default is 2). But, MySQL 8.0 has another component that allows you to filter on rules that you define: log_filter_dragnet. I have explained below step-by-step on how to setup Rule-Based Error Log Filtering using log_filter_dragnet :

INSTALL COMPONENT 'file://component_log_filter_dragnet';
SET GLOBAL log_error_services = 'log_filter_dragnet; log_sink_internal';

To limit information events to no more than one per 60 seconds:

mysql> SET GLOBAL dragnet.log_error_filter_rules =
    -> 'IF prio>=INFORMATION THEN throttle 1/60.';
Query OK, 0 rows affected (0.00 sec)

To throttle  plugin-shutdown messages to only 5 per 5 minutes (300 seconds):

IF err_code == ER_PLUGIN_SHUTTING_DOWN_PLUGIN THEN throttle 1.

To throttle errors and warnings to 1000 per hour and information messages to 100 per hour:

IF prio <= INFORMATION THEN throttle 1000/3600 ELSE throttle 100/3600.

and we can monitor the available dragnet rule:

mysql> select * from global_variables where VARIABLE_NAME like 'dragnet%'G
*************************** 1. row ***************************
 VARIABLE_NAME: dragnet.log_error_filter_rules
VARIABLE_VALUE: IF prio>=INFORMATION THEN throttle 1/60.
1 row in set (0.00 sec)

Conclusion

MySQL 8.0 Error Logging Services are more powerful compared to the versions before and you can now filter error logging much better by creating your own components