Author: fungo
最近在运维 MySQL 中遇到一个神奇的问题，分享给大家。现象是这样的，show binary logs 没有返回结果，flush binary logs 后也不行，
但是 binlog 是正常工作的，show master staus 是有输出的。
mysql> show binary logs;
Empty set (0.00 sec)
mysql> show master status\G
*************************** 1. row ***************************
File: master-bin.000004
Position: 120
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)
mysql> show binary logs;
Empty set (0.00 sec)
mysql> show master status\G
*************************** 1. row ***************************
File: master-bin.000004
Position: 120
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)
mysql> flush binary logs;
Query OK, 0 rows affected (0.01 sec)
mysql> show binary logs;
Empty set (0.00 sec)
mysql> show master status\G
*************************** 1. row ***************************
File: master-bin.000005
Position: 120
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)
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():
reinit_io_cache(index_file, READ_CACHE, (my_off_t) 0, 0, 0);
/* The file ends with EOF or empty line */
while ((length=my_b_gets(index_file, fname, sizeof(fname))) > 1)
{
int dir_len;
ulonglong file_length= 0; // Length if open fails
fname[--length] = '\0'; // remove the newline
protocol->prepare_for_resend();
dir_len= dirname_length(fname);
length-= dir_len;
protocol->store(fname + dir_len, length, &my_charset_bin);
if (!(strncmp(fname+dir_len, cur.log_file_name+cur_dir_len, length)))
file_length= cur.pos; /* The active log, use the active position */
else
{
/* this is an old log, open it and find the size */
if ((file= mysql_file_open(key_file_binlog,
fname, O_RDONLY | O_SHARE | O_BINARY,
MYF(0))) >= 0)
{
file_length= (ulonglong) mysql_file_seek(file, 0L, MY_SEEK_END, MYF(0));
mysql_file_close(file, MYF(0));
}
}
protocol->store(file_length);
if (protocol->write())
{
DBUG_PRINT("info", ("stopping dump thread because protocol->write failed at line %d", __LINE__));
goto err;
}
}
代码逻辑看起来没毛病，心想这问题真是神奇了。。。笔者都准备掏出 gdb 一步一步跟代码看了，在此之前抱着试试看的心态，用 vim 打开了 index 文件，准备人肉看一遍，一打开就发现了可疑的地方，文件内容如下：
./master-bin.000001
./master-bin.000002
./master-bin.000003
./master-bin.000004
./master-bin.000005
有没有看出什么？
细心的读者可能已经发现，第一行是空行，再看下刚的代码，有这么一个判断逻辑:
/* The file ends with EOF or empty line */
while ((length=my_b_gets(index_file, fname, sizeof(fname))) > 1)
空行被认为是文件结束，WTF！心中万头羊驼奔腾。
解法很简单，删了第一行的空行，然后 flush binary logs 生成新的 index 文件把 cache 失效掉，就可以了。
mysql> flush binary logs;
Query OK, 0 rows affected (0.00 sec)
mysql> show binary logs;
+-------------------+-----------+
| Log_name | File_size |
+-------------------+-----------+
| master-bin.000001 | 467 |
| master-bin.000002 | 168 |
| master-bin.000003 | 168 |
| master-bin.000004 | 168 |
| master-bin.000005 | 168 |
| master-bin.000006 | 120 |
+-------------------+-----------+
6 rows in set (0.00 sec)
那么下一个问题来了，为什么第一行会是个空行呢，因为之前主机磁盘被堆满，为了快速清出空间，运维同学把一些老的 binlog 清理掉了，同时 “贴心的” 的把 index 文件也同步手动编辑了，但是因为手残留下了一个空行。。。
这个问题是比较简单的，遇到过一次的话，后面就不会被坑了。。。
从这个问题我们也可以看出，MySQL 在有些时候的逻辑处理非常粗糙简单，对于文件格式没有适当地检测机制，像这种诡异问题就被隐藏吞没掉。如果翻看 commit 历史的话，可以看到“空行就认为是文件结束”的逻辑，在2002年之后就一直是这样的了:-(