唐诡探案外传-MySQL误操作之“寻凶”

序幕：字符集被修改之谜

立秋后的第一天下午，太阳仍不知疲倦地炙烤着大地，办公室内的中央空调不停歇地鼓吹着冷风。某办公楼内，IT部门的阿祖被同事急匆匆地找来，说是系统出现了奇怪的bug，追查之下发现测试环境的MySQL中某个关键表的某个字段的字符集竟然被莫名修改了，从原本的utf8改成了utf16。这让所有人都感到不解，因为最近只有阿祖使用Liquibase计划重新添加索引，由于需要先删除旧索引，他特地请了拥有root权限的测试专家黄老邪来帮忙。但问题是，黄老邪只是删除了索引，而Liquibase的xml中只做了添加索引的操作，并没有去修改字符集，再者是拥有root权限有多人，那么到底是谁修改了字段的字符集呢？难道liquibase有这样的bug？这让真相变得更加扑朔迷离。

在这里插入图片描述

第一幕：排除liquibase的作案可能性

阿祖深吸一口气，整理了下思绪，决定先假定liquibase的生成的语句在测试环境的MySQL执行有问题：即添加索引时修改了字段的字符集。虽然内心99%觉得不可能，但也要先排除掉这个选项。于是使用liquibase命令生成了sql，如下

CREATE UNIQUE INDEX uk_order_no ON tb_order(order_no);

此时其他有root权限同事已将字段字符集改成了正常的utf8，便让黄老邪删除索引后执行上述sql，发现索引添加成功，且字符集没有修改，至此排除liquibase的问题。

第二幕：binlog的追踪之旅

接下来，阿祖继续排查，决定从MySQL的binlog入手。他首先使用普通用户查询MySQL是否开启了binlog

SHOW VARIABLES LIKE 'log_bin%';

+---------------------------------+-----------------------------+
| Variable_name                   | Value                       |
+---------------------------------+-----------------------------+
| log_bin                         | ON                          |
| log_bin_basename                | /xxx/mysql/mysql-bin       |
| log_bin_index                   | /xxx/mysql/mysql-bin.index |
| log_bin_trust_function_creators | OFF                         |
| log_bin_use_v1_row_events       | OFF                         |
+---------------------------------+-----------------------------+

发现开启后，使用root用户查询binlog文件列表

SHOW BINARY LOGS;

+-----------------+------------+-----------+
| Log_name        | File_size  | Encrypted |
+-----------------+------------+-----------+
| mysql-bin.000666 | 1073742177 | No        |
| mysql-bin.000888 | 1006300214 | No        |
+-----------------+------------+-----------+

接着，登录到mysql服务器，进入到上述目录log_bin_index中，寻找到对应的二进制binlog文件，防止对测试环境造成影响，阿祖决定先下载到本地，接着利用mysqlbinlog工具，根据数据库名和操作时间范围，筛选出相关的binlog文件，并将其转换为SQL语句：

mysqlbinlog.exe --start-datetime="2024-08-08 13:30:00" --stop-datetime="2024-08-08 15:00:00" --database=mydatabase /path/to/mysql-bin.000001 > modified_operations.sql

打开modified_operations.sql文件，查找表名关键字，阿祖像侦探一样逐行扫描，终于发现了删除索引和修改字符集的SQL语句。关于此表的操作结果精简如下：

# 第一段 让黄老邪删除索引 执行时间为13:42:09
BEGIN
/*!*/;
# at 382849911
# at 382849989
# at 382850157
#240808 13:42:09 server id 131  end_log_pos 382850188 CRC32 0x010443c7  Xid = 728706665
COMMIT/*!*/;
# at 382850188
#240808 13:42:10 server id 131  end_log_pos 382850385 CRC32 0xa25a5fa4  Query thread_id=22232080  exec_time=0 error_code=0
use `mydatabase`/*!*/;
SET TIMESTAMP=1723095730/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=33/*!*/;
ALTER TABLE `mydatabase`.`tb_order` 

DROP INDEX `order_no`,


# 第二段 字段字符集被修改 执行时间为13:42:28
#240808 13:42:28 server id 131  end_log_pos 382905001 CRC32 0xb9cc6875  Query thread_id=22232080  exec_time=1 error_code=0
SET TIMESTAMP=1723095748/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=33/*!*/;
ALTER TABLE `mydatabase`.`tb_order` 

MODIFY COLUMN `order_no` varchar(100) CHARACTER SET utf16 NULL DEFAULT NULL COMMENT '订单号' AFTER `id`

# 第三段 Liquibase添加索引 执行时间为13:52:53
BEGIN
/*!*/;
# at 384167351
# at 384167440
# at 384167866
#240808 13:52:53 server id 131  end_log_pos 384167897 CRC32 0x717f361e  Xid = 728741825
COMMIT/*!*/;
# at 384167897
#240808 13:52:54 server id 131  end_log_pos 384168058 CRC32 0x397934e7  Query thread_id=22232199  exec_time=0 error_code=0
SET TIMESTAMP=1723096374/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
CREATE UNIQUE INDEX uk_order_no ON tb_order(order_no)

其中第一段删除索引和第二段修改字符集，执行时间只差了19秒，合理怀疑是黄老邪操作，但黄老邪拒不承认，表示根本不可能是他操作的。且日志中这些记录只显示了操作内容，也确实未指明操作者是谁。

第三幕：Navicat的意外线索

不甘心就此放弃，阿祖又尝试从Navicat的本地日志中寻找蛛丝马迹。使用下述按键查看本地执行日志

CRTL+H 或者 CRTL+L

遗憾的是，由于版本限制，Navicat并未记录足够的操作日志。不过，一个念头在他脑海中闪过：会不会是在使用Navicat查看表结构时，不小心修改了字符集？这种误操作虽然罕见，但也并非不可能。此时有些烦躁，感觉已经接近真相但求而不得！

第四幕：Thread_id的真相揭露

就在阿祖准备接受这个不太确定的推测时，binlog中的一个细节再次引起了他的注意。通过比对，他发现删除索引和修改字符集的操作都来自同一个thread_id：22232080。
阿祖立刻行动，使用root用户登录MySQL，执行SHOW PROCESSLIST;命令，并导出结果。

SHOW PROCESSLIST;
+----------+------------+--------------------+----------------+---------+-------+-------+------------------+
| Id       | User       | Host               | db             | Command | Time  | State | Info             |
+----------+------------+--------------------+----------------+---------+-------+-------+------------------+
| 22220001 | dev_select | 10.98.98.90:62192  | testdb         | Sleep   | 22724 |       | NULL             |
| 22220002 | dev_select | 10.98.98.90:62195  | testdb         | Sleep   | 19917 |       | NULL             |
| 22220003 | dev_select | 10.98.98.90:62196  | testdb         | Sleep   | 19917 |       | NULL             |
| 22220004 | dev_select | 10.98.98.90:59780  | testdb         | Sleep   | 19917 |       | NULL             |
| 22232080 | root       | 10.98.98.160:58321 | mydatabase     | Sleep   |  1683 |       | NULL             |
...
+----------+------------+--------------------+----------------+---------+-------+-------+------------------+

在长长的列表中，他找到了thread_id为22232080的记录，让黄老邪查看本机ip后，其对应的host正是黄老邪电脑的IP地址。

第五幕：真相大白

面对铁证如山，黄老邪虽然没有印象操作过，但也不得不承认了事实。阿祖试着复现了“凶案”现场，在使用Navicat查看表结构时，鼠标不小心滑过字符集设置，当鼠标滚轮滚动时，字符集便被修改了。
“黄老邪啊黄老邪，你可真是邪门啊，哈哈哈哈！这下得请客喝奶茶了吧”阿祖笑着摇了摇头，但心中也暗自庆幸，总算找到了问题的根源。

在这里插入图片描述

尾声：教训与反思

这次事件不仅解决了系统的bug，也给所有同事上了一堂生动的课。大家纷纷表示，以后在使用具有修改权限的工具时，一定要更加小心谨慎，避免类似的误操作再次发生。而黄老邪，则因这次“意外”的壮举，被大家戏称为“字符集杀手”，当然，这只是同事间的一个善意的玩笑罢了。同时阿祖也在反思，如果黄老邪navicat关了还能查询到这个线程id吗？

彩蛋及下集看点：

昏暗的灯光下，保安室监控里，黄老邪在删除好索引后，便锁好了屏幕，去上厕所摸鱼去了，其他同事也在各自忙着自己的事情，办公室里一如往常的吵闹。突然！空气猛地变得肃静起来！黄老邪电脑屏幕亮了，屏幕上输入了密码解锁，并且用navicat打开了表结构，最终修改了字符集，并点击了保存，然后又把屏幕锁上，整个过程一气呵成，且无人察觉。最后，昏暗的保安室里，隐约听得一阵阵狂妄和阴森的笑声~

在这里插入图片描述