Dive into MySQL Error

2018/09/21 db tech showcase Tokyo 2018
https://www.db-tech-showcase.com/dbts/tokyo

Transcript

1. Dive into MySQL Error 第二雑学研究部、略してダイブ 2018/09/21 yoku0825 db tech showcase 2018
2. おはようご ざいます 1/81
3. ついに最終日を迎 えたdb tech showcase Tokyo 2018 2/81
4. 楽しんで ますか？ 3/81
5. 楽しいで すよね :) 4/81
6. いいはなし いっぱい 5/81
7. でもそろそ ろみなさん 6/81
8. コードが恋しく なってきた頃なん じゃないかと思い ます 7/81
9. データ ベース 8/81
10. の 9/81
11. コードが 10/81
12. 恋しいで すよね :D 11/81
13. って言っておいて ほとんどソース コード出てきませ ん :-P 12/81
14. ところで 13/81
15. 昨日まで は確かに 14/81
16. 　 15/81
17. (つд⊂)ｺﾞ ｼｺﾞｼ 16/81
18. 　 17/81
19. 　　_, ._ （；ﾟ Дﾟ） …！？ 18/81
20. 1日目、懇親会後 石川さん「おっ久しぶり。今年は何かしゃべらないの？」 おれ「今年はお呼ばれしてないんですよー＞＜」 石川さん「あれ？ 確かまだ枠あるよね」 おれ「えっ」 石川さん「3日目の朝イチ、やる？」 おれ「やります」 19/81
21. インサイトテクノロジー 石川さん、松尾さん 本当にありがとうござい ますm(＿ ＿)m 20/81
22. Be Crazy!! 21/81
23. ＼おはようございます／ yoku0825＠とある企業のDBA オラクれない ‐ ポスグれない ‐ マイエスキューエる ‐ 生息域 Twitter: @yoku0825 ‐ Blog: 日々の覚書 ‐ 日本MySQLユーザ会副代表 ‐ MySQL Casual ‐ 22/81
24. Dive into MySQL Error 23/81
25. MySQLのエ ラーの話をし ます 24/81
26. MySQLのエラーってこんなやつ ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/tmp/mysql.sock' (2) 25/81
27. MySQLのエラーってこんなやつ 1130 - SQLSTATE[HY000] [1130] Host ‘172.19.133.50’ is not allow ed to connect to this MySQL server in /usr/local/../connection.ph p on line 100 26/81
28. まずは大分類 1000番台、3000番台, 10000超はサーバーのエラーコード 3000番台は5.7から、10000超は8.0で導入された ‐ 2000番台はクライアント（libmysqlclient.so）のエラー コード よって2000番台はどのクライアントライブラリーを使うかで変わる ‐ 27/81
29. 最初につけられるアタリ クライアントサイドのエラーなら、そもそもサーバーに到達 していないか可能性がある ネットワーク経路的な問題が一番多い気がする ‐ クライアントサイドエラーでも、サーバーがエラーに絡んで いることもある クライアントライブラリーの互換性の問題 ‐ サーバー側からのコネクション強制切断 ‐ 28/81
30. 2002: CR_CONNECTION_ERROR ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/tmp/mysql.sock' (2) 29/81
31. 2000番台エラーの特徴 サーバーから切られた以外の理由の場合、OSエラーコード が載っていることが多い 例えばLinuxなら #define ENOENT 2 /* No such file or directory */ #define ENOSPC 28 /* No space left on device */ #define ETIMEDOUT 110 /* Connection timed out */ #define ECONNREFUSED 111 /* Connection refused */ #define EHOSTUNREACH 113 /* No route to host */ 30/81
32. 2002: CR_CONNECTION_ERROR ERROR 2002 (HY000): Can't connect to local MySQL server through s ocket '/tmp/mysql.sock' (2) $ perror 2 OS error code 2: No such file or directory MySQL error code MY-000002: Error reading file '%s' (OS errno %d - %s) 31/81
33. 2000番台エラーの特徴 perror コマンドでは調べられ ない パッケージ的にサーバーの付属ユーティリティーだから、だと思う ‐ MySQL :: MySQL 8.0 Reference Manual :: 4.8.2 perror — Explain Error Codes ‐ OSエラーコードは perror コマンドで引ける ‐ OSエラーコードはたまにMySQLサーバーのエラーコードとカブるの で見失わないように… ‐ perror についてはあとで詳しく ‐ 32/81
34. 2003: CR_CONN_HOST_ERROR $ mysql -h10.0.0.1 ERROR 2003 (HY000): Can't connect to MySQL server on '10.0.0.1' (110) $ perror 2003 110 Illegal error code: 2003 OS error code 110: Connection timed out 33/81
35. 同じ2003のタイムアウトでもどっちがタイムアウトさせ るかによって違ったり mysql_options(mysql, MYSQL_OPT_READ_TIMEOUT, 1); mysql_real_connect(mysql); 2003: Can't connect to MySQL server on '192.168.225.201' (4) $ perror 4 OS error code 4: Interrupted system call MySQL error code MY-000004: Error on close of '%s' (OS errno %d - %s) 34/81
36. 2000番台でもサーバーの都合も含むもの サーバー側のアイドルタイマー（wait_timeout）に引っか かってサーバー側から一方的にコネクションを切断されたり KILLステートメントで切断されたり mysql80 11> SELECT NOW(); ERROR 2006 (HY000): MySQL server has gone away mysql80 13> SELECT NOW(); ERROR 2013 (HY000): Lost connection to MySQL server during query 35/81
37. 2006: CR_SERVER_GONE_ERROR クエリー投げようと思ったら既にTCP接続が死んでいたパターン mysql-client mysqld waiting querying running receiving 36/81
38. 2013: CR_SERVER_LOST querying .. receivingの間にTCP接続が死んだパターン mysql-client mysqld waiting querying running receiving 37/81
39. 2000番台でもサーバーの都合も含むもの MySQL 8.0でみんなよくググるコレ ERROR 2059 (HY000): Authentication plugin 'caching_sha2_password' cannot be loaded: /usr/mysql/5.6.41/lib/plugin/caching_sha2_pass word.so: cannot open shared object file: No such file or director y 38/81
40. 2059: CR_AUTH_PLUGIN_CANNOT_LOAD クライアントが要求されたプラグインを見つけられないエラー。 mysql-client mysqld TCP Handshake Greeting Message User Negotiation Check user Lookup plugin Serv ... User ... auth ... 39/81
41. 実はもう1種類ある クライアントから送られてきたクライアントケーパビリ ティーで「要求する認証プラグインにクライアントが対応し ていないことがわかっちゃった」のでサーバーから接続を拒 否。 ERROR 1251 (08004): Client does not support authentication protoc ol requested by server; consider upgrading MySQL client 40/81
42. 1251: ER_NOT_SUPPORTED_AUTH_MODE mysql-client mysqld TCP Handshake Greeting Message User Negotiation Check user Lookup plugin Serv ... User ... auth ... 41/81
43. 2000番台エラーの応用（？） レプリケーションスレーブ（のI/Oスレッド）はマスターか ら見ると クライアント しかも必ずlibmysqlclient.so実装のクライアント ‐ Last_IO_Error に2000番台のエラーが出ることがまれにだ がよくある ここで1000番台、2000番台の切り分けをスムーズにこなすとデキる MySQLerっぽい ‐ 42/81
44. Last_IO_ErrorはOSエラーコードが出てくれないのが ちょっと痛い 少なくとも認証失敗（1000番台）でないことはわかる Last_IO_Errno: 2003 Last_IO_Error: error connecting to master 'root@1 27.0.0.1:64057' - retry-time: 60 retries: 1 クライアントサイドエラーコードの一覧は include/ errmsg.h に 43/81
45. おまけ: Connector/J “Communication link failure” って邪悪なやつがいて src/com/mysql/jdbc/ConnectionImpl.java ‐ src/com/mysql/jdbc/ConnectionImpl.java ‐ 更にすごいことには src/com/mysql/jdbc/SQLError.java ‐ 44/81
46. ひどい XD 45/81
47. まずは大分類(again) 1000番台、3000番台, 10000超はサーバーのエラーコード 3000番台は5.7から、10000超は8.0で導入された ‐ 2000番台はクライアント（libmysqlclient.so）のエラー コード よって2000番台はどのクライアントライブラリーを使うかで変わる ‐ 46/81
48. 次ににつけられるアタリ 1000番台、3000番台、10000超ならサーバーが明示的に 「エラー応答」を返している ERRパケットの中には「サーバーサイドエラーコード」 「SQLステート」「エラーメッセージ」が入っている 47/81
49. ERRパケット MySQL :: MySQL Internals Manual :: 14.1.3.2 ERR_Packet 48/81
50. たとえば エラーコード1251 SQLステート08004 エラーメッセージが “Client does not ..” ERROR 1251 (08004): Client does not support authentication protoc ol requested by server; consider upgrading MySQL client 49/81
51. SQLステート サーバーサイドエラーコードとSQLステートは1対多で結び つく なので、積極的にSQLステートを使うクライアントでなければエラー コードの方が追いやすい ‐ Wikipediaさん後は頼んだ SQLSTATE - Wikipedia ‐ 50/81
52. エラーメッセージ 豆だけど実は日本語にできる lc_messages=ja ‐ MySQL :: MySQL 5.6 リファレンスマニュアル :: 10.2 エラーメッ セージ言語の設定 ‐ 51/81
53. 誰得 mysql80 32> SELECT 1 FROM t1; ERROR 1046 (3D000): No database selected mysql80 32> SET lc_messages= 'ja_JP'; Query OK, 0 rows affected (0.01 sec) mysql80 32> SELECT 1 FROM t1; ERROR 1046 (3D000): データベースが選択されていません。 share/errmsg-utf8.txt から “jpn” で始まってる行を探すと 出てきます 最近増えたエラーコードは網羅されていないのでコントリビュート チャンスですね :D ‐ 52/81
54. perrorコマンド $ perror 1046 MySQL error code MY-001046 (ER_NO_DB_ERROR): No database selected $ perror ER_NO_DB_ERROR MySQL error code MY-001046 (ER_NO_DB_ERROR): No database selected 53/81
55. perrorコマンド さっきから何度か出てきている perror コマンド パッケージ的には mysql-server 系に付属している 引数にエラーコードを受けて、エラーメッセージのフォー マットを出力する エラー番号からだけでもエラーメッセージを推測できる ‐ エラー番号からマクロ名が取り出せるのでgrepが捗る ‐ マクロ名しか書いてない（ことはまずないと思うけど）からエラー番 号とメッセージが取れる ‐ MySQL :: MySQL 5.6 リファレンスマニュアル :: 4.8.1 perror — エラーコードの説明 54/81
56. perrorコマンド 一番（？）嬉しいのは、 どこまでが決め打ちメッセージな のか がわかるフォーマットを見られること たとえば 1593: ER_SLAVE_FATAL_ERROR は Slave I/O: The slave I/O thread stops because master and slave ha ve equal MySQL server ids; these ids must be different for replic ation to work (or the --replicate-same-server-id option must be u sed on slave but this does not always make sense; please check th e manual before using it), Error_code: 1593 Slave I/O: The slave I/O thread stops because SET @master_heartbe at_period on master failed. Error: , Error_code: 1593 Slave SQL: Fatal error: Failed to initialize the master info stru cture, Error_code: 1593 55/81
57. 1593: ER_SLAVE_FATAL_ERROR 8.0ではER_BINLOG_FATAL_ERRORになってる…: (；ﾞﾟ’ωﾟ’): perrorで引くとほとんどが可変部分で、このエラーコードが 示すものは “Fatal error” しかない（あとは全部状況で変わ る） $ /usr/mysql/8.0.12/bin/perror 1593 MySQL error code MY-001593 (ER_BINLOG_FATAL_ERROR): Fatal error: %s $ /usr/mysql/5.7.23/bin/perror 1593 MySQL error code 1593 (ER_SLAVE_FATAL_ERROR): Fatal error: %s 56/81
58. じゃあどこでこのバリエーションが生まれるのか？ エラーマクロが分かってればgrepは簡単 $ grep -r -A1 ER_SLAVE_FATAL_ERROR . ... ./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR), ./sql/log_event.cc- "Invalid character set for User var event"); -- ./sql/rpl_slave.cc: mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ./sql/rpl_slave.cc: ER(ER_SLAVE_FATAL_ERROR), ./sql/rpl_slave.cc- "Failed to flush master info."); -- ./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR), ./sql/log_event.cc- "Binlog version not supported"); ... 57/81
59. 慣れてくると mi は master_info のことでI/Oスレッド関連 rli は relay_log_info のことでSQLスレッド関連 それぞれ report は SHOW SLAVE STATUS で表示されるような バッファ（とエラーログ）に記録するためのメソッド $ grep -r -A1 ER_SLAVE_FATAL_ERROR . ... ./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR), ./sql/log_event.cc- "Invalid character set for User var event"); -- ./sql/rpl_slave.cc: mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ./sql/rpl_slave.cc: ER(ER_SLAVE_FATAL_ERROR), ./sql/rpl_slave.cc- "Failed to flush master info."); -- ./sql/log_event.cc: rli->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ./sql/log_event.cc: ER_THD(thd, ER_SLAVE_FATAL_ERROR), ./sql/log_event.cc- "Binlog version not supported"); ... 58/81
60. プログラミング言 語 全く 読めない 方はいますか？ 59/81
61. C怖くないよ 2496 char query_buf[]= "SELECT @@GLOBAL.SERVER_UUID"; .. 2525 if (!mysql_real_query(mysql, STRING_WITH_LEN(query_buf)) && 2526 (master_res= mysql_store_result(mysql)) && 2527 (master_row= mysql_fetch_row(master_res))) 2528 { 2529 if (!strcmp(::server_uuid, master_row[0]) && 2530 !mi->rli->replicate_same_server_id) 2531 { 2532 errmsg= "The slave I/O thread stops because master and slave have equ al " 2533 "MySQL server UUIDs; these UUIDs must be different for " 2534 "replication to work."; 2535 mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ER(ER_SLAVE_FATAL_ERROR ), 2536 errmsg); 2537 // Fatal error 2538 ret= 1; 2539 } sql/rpl_slave.cc 60/81
62. なんとなく わかりません？ 2496 char query_buf[]= "SELECT @@GLOBAL.SERVER_UUID"; .. 2525 if (!mysql_real_query(mysql, STRING_WITH_LEN(query_buf)) && 2526 (master_res= mysql_store_result(mysql)) && 2527 (master_row= mysql_fetch_row(master_res))) 2528 { 2529 if (!strcmp(::server_uuid, master_row[0]) && 2530 !mi->rli->replicate_same_server_id) 2531 { 2532 errmsg= "The slave I/O thread stops because master and slave have equ al " 2533 "MySQL server UUIDs; these UUIDs must be different for " 2534 "replication to work."; 2535 mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ER(ER_SLAVE_FATAL_ERROR ), 2536 errmsg); 2537 // Fatal error 2538 ret= 1; 2539 } sql/rpl_slave.cc 61/81
63. もう1つの視点で 可変部分は呼び出し元から文字列で渡されるので、1593な ら “Fatal error:” の他の部分はソースコードから探しやすい それに対して1046は可変部分がないのでエラーマクロで探 すしかない $ perror 1046 MySQL error code MY-001046 (ER_NO_DB_ERROR): No database selected $ perror 1593 MySQL error code MY-001593 (ER_BINLOG_FATAL_ERROR): Fatal error: %s 62/81
64. もう1つの視点 これは grep -r "UUIDs must be different" . でもたどり着 ける 2496 char query_buf[]= "SELECT @@GLOBAL.SERVER_UUID"; .. 2525 if (!mysql_real_query(mysql, STRING_WITH_LEN(query_buf)) && 2526 (master_res= mysql_store_result(mysql)) && 2527 (master_row= mysql_fetch_row(master_res))) 2528 { 2529 if (!strcmp(::server_uuid, master_row[0]) && 2530 !mi->rli->replicate_same_server_id) 2531 { 2532 errmsg= "The slave I/O thread stops because master and slave have equal " 2533 "MySQL server UUIDs; these UUIDs must be different for " 2534 "replication to work."; 2535 mi->report(ERROR_LEVEL, ER_SLAVE_FATAL_ERROR, ER(ER_SLAVE_FATAL_ERROR), 2536 errmsg); 2537 // Fatal error 2538 ret= 1; 2539 } sql/rpl_slave.cc 63/81
65. もう1つの視点 grep -r "No database selected" . だとテストケースとマ クロの定義部分しか出てこない それはそれで楽しいんですけどね :D ‐ ... ./include/mysqld_ername.h:{ "ER_NO_DB_ERROR", 1046, "No database selected" }, ./mysql-test/r/alter_table.result:ERROR 3D000: No database select ed ./mysql-test/r/create.result:ERROR 3D000: No database selected ./mysql-test/t/information_schema.test:# Bug#38916 Select from I_ S.ROUTINES results in "No database selected" error ./mysql-test/t/sp.test:# Bug#28551 "The warning 'No database sele cted' is reported when calling ... 64/81
66. エラーに触れるつ いでにエラーログ についても触れて おこう 65/81
67. MySQLのエラーログとは実は freopen を使ってstderrとstdoutを向けているだけ 1772 do { 1773 errors = 0; 1774 if (!my_freopen(filename, "a", stderr)) errors++; 1775 if (!my_freopen(filename, "a", stdout)) errors++; 1776 } while (retries-- && errors); 1777 sql/log.cc 66/81
68. lsofで開いているファイルディスクリプターを見るだけで もわかったりする $ lsof -p $(pidof mysqld) .. mysqld 20980 yoku0825 0r CHR 1,3 0t0 1028 /dev/null mysqld 20980 yoku0825 1w REG 253,0 52083 137048897 /usr/mysql/8.0.12/data/error.log mysqld 20980 yoku0825 2w REG 253,0 52083 137048897 /usr/mysql/8.0.12/data/error.log mysqld 20980 yoku0825 3u REG 253,0 65 149633590 /usr/mysql/8.0.12/data/bin.index mysqld 20980 yoku0825 4u REG 253,0 4077 149596931 /usr/mysql/8.0.12/data/innodb_status.20980 .. 67/81
69. stdoutとstderrが繋がっているだけなので プラグインの中で fprintf(stderr, ..) とかやるとフツーに エラーログに出る printデバッグする機会があれば憶えておいて損はないはず ;) ‐ InnoDB Monitor( CREATE TABLE innodb_monitor とか SET GLOBAL innodb_status_output = 1 )がなんでデフォルトで エラーログに書かれるのか… InnoDBからするとエラーログに書いてるつもりはなくて、単に標準 エラー出力に書いているだけ ‐ ロガープロセスみたいなのがいるわけではない 68/81
70. stdoutとstderrが繋がっているだけなので おもむろにエラーログの書式をガン無視したInnoDBのログ に遭遇したことってありません？ タイムスタンプとかログレベルとか一切ないやつ ‐ 180731 13:29:08 [Note] InnoDB: 5.5.61 started; log sequence numbe r 1625977 InnoDB: Error: page 1234 log sequence number InnoDB: is in the future! Current system log sequence number 1625 977 InnoDB: Your database may be corrupt or you may have copied the I nnoDB InnoDB: tablespace but not the InnoDB log files. See" InnoDB: https://dev.mysql.com/../forcing-innodb-recovery.html InnoDB: for more information. 69/81
71. stdoutとstderrが繋がっているだけなので 553 fprintf(stderr, 554 " InnoDB: Error: page %lu log sequence number" 555 " %llu\n" 556 "InnoDB: is in the future! Current system " 557 "log sequence number %llu.\n" 558 "InnoDB: Your database may be corrupt or " 559 "you may have copied the InnoDB\n" 560 "InnoDB: tablespace but not the InnoDB " 561 "log files. See\n" 562 "InnoDB: " REFMAN "forcing-innodb-recovery.html\n" 563 "InnoDB: for more information.\n", 564 (ulong) mach_read_from_4(read_buf 565 + FIL_PAGE_OFFSET), 566 mach_read_from_8(read_buf + FIL_PAGE_LSN), 567 current_lsn); 5 storage/innobase/buf/buf0buf.c 70/81
72. 最近のはちゃんとエ ラーログに書くため の関数を呼んでるの で優しくなった 71/81
73. エラーログで ついでに思い 出した 72/81
74. 有名なアレ 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. key_buffer_size=67108864 read_buffer_size=2093056 max_used_connections=0 max_connections=3000 threads_connected=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 30773512 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. 73/81
75. 実はこのメッセージはハードコード 115 my_safe_printf_stderr("%s", 116 "This could be because you hit a bug. It is also " 117 "possible that this binary\n" 118 "or one of the libraries it was linke d against is " 119 "corrupt, improperly built,\n" 120 "or misconfigured. This error can als o be caused by " 121 "malfunctioning hardware.\n"); sql/signal_handler.cc 74/81
76. 未だに key_buffer_size がどうこう言うのも 単にハードコードされてるのを直してないだけ innodb_buffer_pool_size が出てこないのも単に直してないだけ ‐ 130 my_safe_printf_stderr("key_buffer_size=%lu\n", 131 (ulong)dflt_key_cache->key_cache_mem_ size); sql/signal_handler.cc 75/81
77. handle_fatal_signal に対する雑な所感 signal 11(SIGSEGV)だと本物の（？）バグっぽさが上がる signal 6(SIGABRT)はAssertionに引っかかってるケース 多くの場合、InnoDBのページ破損とかになるんじゃなかろうか ‐ この場合はバグじゃないからあの固定メッセージ出さなくて良い気 が… ‐ 76/81
78. あと、何かの名残 5.1, 5.5, 5.6にはこんな分岐があった 未実装のまま5.7からは消えてる ‐ 1154 switch (error_log_printer) { 1155 case LOG_FILE: 1156 error_log_handler_list[0]= file_log_handler; 1157 error_log_handler_list[1]= 0; 1158 break; 1159 /* these two are disabled for now */ 1160 case LOG_TABLE: 1161 DBUG_ASSERT(0); 1162 break; 1163 case LOG_TABLE|LOG_FILE: 1164 DBUG_ASSERT(0); 1165 break; 1166 } sql/log.cc 77/81
79. それを言い出すとmysqld_safeのエラーログ これもシェルスクリプトの中で各コマンドの標準出力と標準 エラー出力をリダイレクトでファイルに向けているだけ mysqldのログがsyslogに吐けるようになったのは最近だけ どmysqld_safeのログが昔っから吐けたのは単にloggerコマ ンドを使えば良かったから mysqldの方はログを書き込む関数を呼ばずにあちこちまちまちに書い てたのでそれを統合するところから始まったんだと思う ‐ そんなのもあってログ用の関数はメジャーバージョンのたびにガリガ リ書き換わってるので、ストレージエンジンとかで真面目にそこを呼 んでいるお行儀の良いやつはマクロで大変な気がする ‐ 78/81
80. おっと何 の話だ 79/81
81. まとめ エラーにはクライアントサイドエラーとサーバーサイドエ ラーがある サーバーサイドエラーはものによって汎用的すぎるエラーが あったり、特化しすぎたエラーがあったりでグレッパビリ ティーが変わる エラーログ駆動でソースコードを読むのは楽しい See also, エラーログドリブン ソースコードリーディング(ただし MySQLに限る) | GMOメディア エンジニアブログ ‐ 80/81
82. Any Questions and/or Suggestions? 81/81