Dive into MySQL Error

0deae06ab5d86b39feeec2e23a30b88a?s=47 yoku0825
September 21, 2018
910

Dive into MySQL Error

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

0deae06ab5d86b39feeec2e23a30b88a?s=128

yoku0825

September 21, 2018
Tweet

Transcript

  1. 10.
  2. 16.
  3. 18.
  4. 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
  5. 30.

    2002: CR_CONNECTION_ERROR ERROR 2002 (HY000): Can't connect to local MySQL

    server through socket '/tmp/mysql.sock' (2) 29/81
  6. 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
  7. 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
  8. 33.

    2000番台エラーの特徴 perror コマンドでは調べられ ない パッケージ的にサーバーの付属ユーティリティーだから、だと思う ‐ MySQL :: MySQL 8.0

    Reference Manual :: 4.8.2 perror — Explain Error Codes ‐ OSエラーコードは perror コマンドで引ける ‐ OSエラーコードはたまにMySQLサーバーのエラーコードとカブるの で見失わないように… ‐ perror についてはあとで詳しく ‐ 32/81
  9. 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
  10. 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
  11. 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
  12. 44.
  13. 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
  14. 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
  15. 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
  16. 55.

    perrorコマンド さっきから何度か出てきている perror コマンド パッケージ的には mysql-server 系に付属している 引数にエラーコードを受けて、エラーメッセージのフォー マットを出力する エラー番号からだけでもエラーメッセージを推測できる

    ‐ エラー番号からマクロ名が取り出せるのでgrepが捗る ‐ マクロ名しか書いてない(ことはまずないと思うけど)からエラー番 号とメッセージが取れる ‐ MySQL :: MySQL 5.6 リファレンスマニュアル :: 4.8.1 perror — エラーコードの説明 54/81
  17. 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
  18. 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
  19. 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
  20. 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
  21. 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
  22. 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
  23. 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
  24. 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
  25. 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
  26. 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
  27. 69.

    stdoutとstderrが繋がっているだけなので プラグインの中で fprintf(stderr, ..) とかやるとフツーに エラーログに出る printデバッグする機会があれば憶えておいて損はないはず ;) ‐ InnoDB

    Monitor( CREATE TABLE innodb_monitor とか SET GLOBAL innodb_status_output = 1 )がなんでデフォルトで エラーログに書かれるのか… InnoDBからするとエラーログに書いてるつもりはなくて、単に標準 エラー出力に書いているだけ ‐ ロガープロセスみたいなのがいるわけではない 68/81
  28. 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
  29. 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
  30. 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
  31. 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
  32. 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