问题背景

最近在运维 MySQL 中遇到一个神奇的问题，分享给大家。现象是这样的，show binary logs 没有返回结果，flush binary logs 后也不行， 但是 binlog 是正常工作的，show master staus 是有输出的。

  1. mysql> show binary logs;
  2. Empty set (0.00 sec)
  4. mysql> show master status\G
  5. *************************** 1. row ***************************
  6.              File: master-bin.000004
  7.          Position: 120
  8.      Binlog_Do_DB:
  9.  Binlog_Ignore_DB:
  10. Executed_Gtid_Set:
  11. 1 row in set (0.00 sec)
  13. mysql> show binary logs;
  14. Empty set (0.00 sec)
  16. mysql> show master status\G
  17. *************************** 1. row ***************************
  18.              File: master-bin.000004
  19.          Position: 120
  20.      Binlog_Do_DB:
  21.  Binlog_Ignore_DB:
  22. Executed_Gtid_Set:
  23. 1 row in set (0.00 sec)
  25. mysql> flush binary logs;
  26. Query OK, 0 rows affected (0.01 sec)
  28. mysql> show binary logs;
  29. Empty set (0.00 sec)
  31. mysql> show master status\G
  32. *************************** 1. row ***************************
  33.              File: master-bin.000005
  34.          Position: 120
  35.      Binlog_Do_DB:
  36.  Binlog_Ignore_DB:
  37. Executed_Gtid_Set:
  38. 1 row in set (0.00 sec)
  40. mysql>

问题排查

这个问题是笔者第一次遇到，从问题的现象看，binlog 是没有问题的，可以正常写入和切换，只是 show 命令看不到 binlog 文件列表，我们知道 MySQL 是用一个 index 元文件来维护当前使用的 binlog 的，而 show binary logs 也是读这个文件来展示的，因此问题应该出在 index 文件上。

我们首先检查 index 文件的权限，发现也是没问题的，mysqld 进程用户是有读写权限的，然后我们用 tail -f 命令监控 index 文件，另一个窗口连接mysql，执行 flush binary logs，发现新产生的 binlog 文件也是会追加到 index 里。越排查越觉得诡异，并且没有排查下去的思路了，难道是 show binary logs 逻辑有问题，翻开代码确认了下，主体逻辑非常简单，就是从 index 文件头开始遍历，一行对应一个 binlog 文件，每一个 binlog 文件都获取下文件size，然后把结果发给客户端，详见 rpl_master.cc:show_binlogs():

  1.   reinit_io_cache(index_file, READ_CACHE, (my_off_t) 0, 0, 0);
  3.   /* The file ends with EOF or empty line */
  4.   while ((length=my_b_gets(index_file, fname, sizeof(fname))) > 1)
  5.   {
  6.     int dir_len;
  7.     ulonglong file_length= 0;                   // Length if open fails
  8.     fname[--length] = '\0';                     // remove the newline
  10.     protocol->prepare_for_resend();
  11.     dir_len= dirname_length(fname);
  12.     length-= dir_len;
  13.     protocol->store(fname + dir_len, length, &my_charset_bin);
  15.     if (!(strncmp(fname+dir_len, cur.log_file_name+cur_dir_len, length)))
  16.       file_length= cur.pos;  /* The active log, use the active position */
  17.     else
  18.     {
  19.       /* this is an old log, open it and find the size */
  20.       if ((file= mysql_file_open(key_file_binlog,
  21.                                  fname, O_RDONLY | O_SHARE | O_BINARY,
  22.                                  MYF(0))) >= 0)
  23.       {
  24.         file_length= (ulonglong) mysql_file_seek(file, 0L, MY_SEEK_END, MYF(0));
  25.         mysql_file_close(file, MYF(0));
  26.       }
  27.     }
  28.     protocol->store(file_length);
  29.     if (protocol->write())
  30.     {
  31.       DBUG_PRINT("info", ("stopping dump thread because protocol->write failed at line %d", __LINE__));
  32.       goto err;
  33.     }
  34.   }

代码逻辑看起来没毛病，心想这问题真是神奇了。。。笔者都准备掏出 gdb 一步一步跟代码看了，在此之前抱着试试看的心态，用 vim 打开了 index 文件，准备人肉看一遍，一打开就发现了可疑的地方，文件内容如下：

  2. ./master-bin.000001
  3. ./master-bin.000002
  4. ./master-bin.000003
  5. ./master-bin.000004
  6. ./master-bin.000005

有没有看出什么？

细心的读者可能已经发现，第一行是空行，再看下刚的代码，有这么一个判断逻辑:

  1.   /* The file ends with EOF or empty line */
  2.   while ((length=my_b_gets(index_file, fname, sizeof(fname))) > 1)

空行被认为是文件结束，WTF！心中万头羊驼奔腾。

解法很简单，删了第一行的空行，然后 flush binary logs 生成新的 index 文件把 cache 失效掉，就可以了。

  1. mysql> flush binary logs;
  2. Query OK, 0 rows affected (0.00 sec)
  4. mysql> show binary logs;
  5. +-------------------+-----------+
  6. | Log_name          | File_size |
  7. +-------------------+-----------+
  8. | master-bin.000001 |       467 |
  9. | master-bin.000002 |       168 |
  10. | master-bin.000003 |       168 |
  11. | master-bin.000004 |       168 |
  12. | master-bin.000005 |       168 |
  13. | master-bin.000006 |       120 |
  14. +-------------------+-----------+
  15. 6 rows in set (0.00 sec)

那么下一个问题来了，为什么第一行会是个空行呢，因为之前主机磁盘被堆满，为了快速清出空间，运维同学把一些老的 binlog 清理掉了，同时 “贴心的” 的把 index 文件也同步手动编辑了，但是因为手残留下了一个空行。。。

问题总结

这个问题是比较简单的，遇到过一次的话，后面就不会被坑了。。。

从这个问题我们也可以看出，MySQL 在有些时候的逻辑处理非常粗糙简单，对于文件格式没有适当地检测机制，像这种诡异问题就被隐藏吞没掉。如果翻看 commit 历史的话，可以看到“空行就认为是文件结束”的逻辑，在2002年之后就一直是这样的了:-(