TL;DR

log_error_verbosity のデフォルトが3(Error + Warning + Note) から 2(Error + Warning)に変更されたよ
MySQL 8.0.4からエラーログのフィールドに error_id が追加されたよ
“Note”, “Warning”, “Error”の3つだった severity に “System”が追加されたよ
- “System” は “Error” より強いレベルなので log_error_verbosity が1(最小値)でも出力される
↓こんな出力になるよ


2018-01-25T01:22:56.821986Z 0 [System] [MY-010116] /usr/mysql/8.0.4/bin/mysqld (mysqld 8.0.4-rc) starting as process 9206 ...

Messages written to the error log by the log_sink_internal log writer component now contain an error-ID indicator. This ID has a format of [error_id]. It follows the severity indicator and precedes the message text. For more information, see Error Log Message Format.

MySQL :: MySQL 8.0 Release Notes :: Changes in MySQL 8.0.4 (2018-01-23, Release Candidate)

ということで、エラーログのフィールドがちょっと変わっている。

5.7.21の起動ログはこんな感じで

2018-01-25T01:24:06.510686Z mysqld_safe Logging to '/usr/mysql/5.7.21/data/error.log'.
2018-01-25T01:24:06.555127Z mysqld_safe Starting mysqld daemon with databases from /usr/mysql/5.7.21/data
2018-01-25T01:24:06.566872Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2018-01-25T01:24:06.567016Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
..
2018-01-25T10:24:07.842676+09:00 0 [Warning] 'tables_priv' entry 'user mysql.session@localhost' ignored in --skip-name-resolve mode.
2018-01-25T10:24:07.842747+09:00 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2018-01-25T10:24:07.867477+09:00 0 [Note] Event Scheduler: Loaded 0 events
2018-01-25T10:24:07.867745+09:00 0 [Note] /usr/mysql/5.7.21/bin/mysqld: ready for connections.
Version: '5.7.21-log'  socket: '/usr/mysql/5.7.21/data/mysql.sock'  port: 64057  Source distribution
2018-01-25T10:24:07.906647+09:00 0 [Note] InnoDB: Buffer pool(s) load completed at 180125 10:24:07

8.0.4はこんな感じ。

2018-01-25T01:24:09.351792Z mysqld_safe Logging to '/usr/mysql/8.0.4/data/error.log'.
2018-01-25T01:24:09.415752Z mysqld_safe Starting mysqld daemon with databases from /usr/mysql/8.0.4/data
2018-01-25T01:24:09.596184Z 0 [Warning] [MY-010139] Changed limits: max_open_files: 1024 (requested 8161)
2018-01-25T01:24:09.596340Z 0 [Warning] [MY-010142] Changed limits: table_open_cache: 431 (requested 4000)2018-01-25T01:24:14.383583Z 0 [Warning] [MY-010323] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
..
2018-01-25T01:24:14.412655Z 0 [Warning] [MY-010330] 'tables_priv' entry 'user mysql.session@localhost' ignored in --skip-name-resolve mode.
2018-01-25T01:24:14.412724Z 0 [Warning] [MY-010330] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2018-01-25T01:24:14.437421Z 0 [System] [MY-010931] /usr/mysql/8.0.4/bin/mysqld: ready for connections. Version: '8.0.4-rc-log'  socket: '/usr/mysql/8.0.4/data/mysql.sock'  port: 64080  Source distribution.

人間が読む分にはそんなに情報量は変わっていない。エラーIDでのググラビリティが上がるのかなって何この ORA-* 的な MY-* はｗｗ

Systemで出力されるログにはどんなのがあるかざっと調べてみる。

$ grep -A1 SYSTEM_LEVEL sql/*.cc | grep ER
sql/mysqld.cc:    LogErr(SYSTEM_LEVEL, ER_SERVER_SHUTDOWN_COMPLETE, my_progname);
sql/mysqld.cc:  LogErr(SYSTEM_LEVEL, ER_STARTING_AS,
sql/mysqld.cc:      LogErr(SYSTEM_LEVEL, ER_NORMAL_SHUTDOWN, my_progname);
sql/mysqld.cc-            .lookup(ER_SERVER_STARTUP_MSG,
sql/rpl_slave.cc:    LogErr(SYSTEM_LEVEL, ER_RPL_SLAVE_DUMP_THREAD_KILLED_BY_MASTER,
sql/rpl_slave.cc-           ER_RPL_SLAVE_CONNECTED_TO_MASTER_REPLICATION_STARTED,
sql/rpl_slave.cc-               ER_RPL_SLAVE_CONNECTED_TO_MASTER_REPLICATION_RESUMED,
sql/rpl_slave.cc:    LogErr(SYSTEM_LEVEL, ER_SLAVE_CHANGE_MASTER_TO_EXECUTED,
sql/sql_parse.cc:      LogErr(SYSTEM_LEVEL, ER_PARSER_TRACE,
sql/sql_parse.cc:        LogErr(SYSTEM_LEVEL, ER_PARSER_TRACE, thd->query().str);
sql/sql_restart_server.cc:  LogErr(SYSTEM_LEVEL, ER_RESTART_RECEIVED_INFO,
sql/sys_vars.cc:  LogErr(SYSTEM_LEVEL, ER_CHANGED_GTID_MODE,
sql/sys_vars.cc:  LogErr(SYSTEM_LEVEL, ER_GTID_PURGED_WAS_UPDATED,
sql/sys_vars.cc:  LogErr(SYSTEM_LEVEL, ER_GTID_EXECUTED_WAS_UPDATED,
sql/xa.cc:    LogErr(SYSTEM_LEVEL, ER_XA_STARTING_RECOVERY);
sql/xa.cc:    LogErr(SYSTEM_LEVEL, ER_XA_RECOVERY_DONE);

全部は見てないけど、ER_SERVER_SHUTDOWN_COMPLETEとかER_NORMAL_SHUTDOWNとかは5.7とそれ以前ではNoteだった（ log_error_verbosity < 3に設定すると見えなくなって焦ったやつ ⇒ 日々の覚書: MySQL 5.7では”[Note] mysqld: ready for connections”がどっかいった？（いってなかった）ので、 log_error_verbosity = 2 をデフォルトにしても問題ないように布石を打ったのかしらん。これは良い感じだ。

なおこの MY-* の数字は perror で引くことができる。

$ /usr/mysql/8.0.4/bin/perror  010116
MySQL error code 10116 (ER_STARTING_AS): %s (mysqld %s) starting as process %lu ...

$ /usr/mysql/8.0.4/bin/perror 010931
MySQL error code 10931 (ER_SERVER_STARTUP_MSG): %s: ready for connections. Version: '%s'  socket: '%s'  port: %d  %s.

大した話ではないけどなかなか面白かった。

日々の覚書

GA

2018/01/25

MySQL 8.0.4でエラーログのフォーマットが微妙に変わった

TL;DR

0 件のコメント :

コメントを投稿