一次 MySQL Docker 容器日志爆满引发的登录超时排查

最近处理了一次比较典型的线上问题：业务系统登录接口突然开始超时。乍一看像是后端服务卡住了，但最后排查下来，问题并不在登录接口本身，而是 MySQL 容器里有一个异常线程长时间卡住，持续刷 InnoDB 错误日志，导致 Docker 容器日志快速膨胀，同时影响了数据库响应。

这类问题很容易误判。因为用户看到的是“登录超时”，开发第一反应可能会去看接口、看 Nginx、看后端服务状态。但实际线上排查不能只盯着业务代码，还是要顺着整条调用链往下看：后端服务是否正常、数据库是否正常、磁盘是否正常、Docker 日志有没有异常、MySQL 里有没有长时间运行的线程。

这篇文章就记录一下这次问题的排查过程、处理方式，以及后续怎么避免类似问题再次发生。

---

一、问题现象

业务系统登录时出现超时，请求迟迟没有返回。

登录超时一般说明后端某个环节响应变慢，常见方向包括：

1. 后端服务本身卡住
2. 数据库响应慢
3. 数据库连接池被打满
4. MySQL 存在锁等待或异常线程
5. 服务器磁盘或 I/O 异常
6. Docker 容器日志异常膨胀

这类问题不能只看接口日志，因为接口超时往往只是表象。真正的原因可能在数据库，也可能在服务器资源层面。

---

二、先看磁盘：发现 Docker 日志异常增长

第一步先看服务器磁盘情况：

df -h

这里有一个容易误解的点：如果服务器上跑了 Docker，df -h 里可能会看到很多 overlay 挂载项。

类似这样：

overlay  99G  45G  50G  48% /var/lib/docker/rootfs/overlayfs/...

这些 overlay 不是多块独立磁盘，而是 Docker 容器文件系统的挂载点，不能把每一行的已用空间简单累加。真正要关注的是根分区、Docker 数据目录所在分区，以及日志目录的实际占用。

接着查看日志占用：

du -ah /var/log /var/lib/docker/containers 2>/dev/null | sort -rh | head -30

很快发现一个 Docker 容器日志文件已经到了 4.4G：

4.4G /var/lib/docker/containers/xxx/xxx-json.log

这说明当前至少存在一个明确问题：某个容器正在疯狂写日志。

---

三、确认日志属于哪个容器

接下来需要确认这个 4.4G 的日志文件到底属于哪个容器。

执行：

docker inspect -f 'name={{.Name}} image={{.Config.Image}} status={{.State.Status}} log={{.LogPath}}' <container_id>

结果显示：

name=/mes-hub-db
image=mysql:8.0
status=running
log=/var/lib/docker/containers/...-json.log

也就是说，日志爆满的容器是 MySQL 容器。

到这里，排查方向就从“登录接口慢”转向了“数据库容器异常”。

---

四、排除 MySQL 普通日志和慢查询日志

MySQL 日志变大，第一反应可能是 general log 或 slow query log 被打开了。

所以先查一下 MySQL 日志配置：

SHOW VARIABLES LIKE 'general_log';
SHOW VARIABLES LIKE 'slow_query_log';
SHOW VARIABLES LIKE 'log_error_verbosity';

结果是：

general_log = OFF
slow_query_log = OFF
log_error_verbosity = 2

这说明日志暴涨不是因为全量 SQL 日志，也不是慢查询日志导致的。

那为什么 Docker 的 json.log 会这么大？

原因是 MySQL 进程把错误信息持续输出到了标准错误流，而 Docker 默认的 json-file 日志驱动会把这些内容写到容器日志文件里。换句话说，MySQL 里面一定有东西在不断报错。

---

五、查看 MySQL 容器日志尾部

因为日志文件已经有 4.4G，直接执行 docker logs 可能会很慢，所以更合适的方式是直接看日志文件尾部。

日志里反复出现类似内容：

[Warning] [MY-012637] [InnoDB] 16384 bytes should have been read. Only 0 bytes read. Retrying for the remaining bytes.
[Warning] [MY-012638] [InnoDB] Retry attempts for reading partial data failed.
[ERROR] [MY-012642] [InnoDB] Tried to read 16384 bytes at offset 0, but was only able to read 0
[ERROR] [MY-012592] [InnoDB] Operating system error number 11 in a file operation.
[ERROR] [MY-012596] [InnoDB] Error number 11 means 'Resource temporarily unavailable'

这类日志已经不是普通慢 SQL，也不像正常数据迁移。

从日志来看，InnoDB 期望读取 16KB 数据页，但实际只读到了 0 字节，并且重试失败。也就是说，MySQL 在访问某些表空间文件或数据页时遇到了异常。

这时不能贸然直接清日志或者重启，必须继续确认 MySQL 当前线程状态。

---

六、查看 MySQL 当前线程

执行：

SHOW FULL PROCESSLIST;

发现一个异常线程：

Id:      412
User:    mes_hub_user
Host:    112.124.239.53:31398
Command: Query
Time:    66603
State:   Opening tables
Info:    SELECT PLUGIN_STATUS FROM INFORMATION_SCHEMA.PLUGINS WHERE PLUGIN_NAME LIKE 'keyring_rds'

再次查看时，这个线程还在，Time 继续增长，已经卡住超过 18 个小时。

这里有两个关键信息。

第一，线程状态是：

Opening tables

说明它卡在打开表的阶段。

第二，执行的 SQL 是：

SELECT PLUGIN_STATUS
FROM INFORMATION_SCHEMA.PLUGINS
WHERE PLUGIN_NAME LIKE 'keyring_rds'

这不是正常业务登录 SQL，也不像普通数据迁移 SQL。

更关键的是，MySQL 错误日志里的线程编号和 SHOW FULL PROCESSLIST 里的异常线程编号一致，都是 412。这基本可以判断：持续刷 InnoDB 错误日志的源头，大概率就是这个异常卡住的查询线程。

---

七、为什么 KILL 不一定生效？

发现异常线程后，第一反应肯定是尝试 kill 掉它。

可以执行：

KILL QUERY 412;

或者：

KILL 412;

但是这次问题里，KILL 并没有立刻释放线程。

这个现象并不奇怪。MySQL 的 KILL 不是操作系统层面的强制杀线程，它更像是给数据库线程打一个“退出标记”。线程需要运行到可以检查这个标记的位置，才会真正退出。

如果线程卡在 Opening tables、InnoDB 文件读取、底层 I/O 等待这类位置，就可能无法及时响应 KILL。

所以这次不能指望单靠 KILL 恢复。

---

八、最终处理：先备份，再重启 MySQL 容器

因为日志里已经出现 InnoDB 文件读取异常，直接重启数据库存在一定风险。稳妥的处理顺序应该是：

1. 先确认数据库还能访问
2. 能备份就先备份
3. 云服务器环境下可以先做云盘快照
4. 确认备份或快照完成后，再重启 MySQL 容器

完成备份后，重启 MySQL 容器：

docker restart mes-hub-db

重启后，异常卡住的线程被清理，MySQL 服务恢复，业务系统登录也恢复正常。

至此可以确认：本次登录超时并不是登录接口代码问题，而是 MySQL 容器中存在异常卡死线程，持续触发 InnoDB 错误日志，同时影响数据库响应。

---

九、日志文件怎么处理？

对于已经增长到几 GB 的 Docker 日志文件，可以用 truncate 临时清空：

truncate -s 0 /var/lib/docker/containers/xxx/xxx-json.log

这里要注意两点。

第一，不建议直接 rm 删除 Docker 正在使用的日志文件。容器进程可能还持有文件句柄，删除后不一定真正释放空间，反而容易造成排查混乱。

第二，truncate 只是在清理日志文件大小，不会解决根因。如果 MySQL 异常线程还在，日志还是会继续增长。所以一定要先处理根因，再清理日志。

---

十、这次问题的完整排查链路

整体排查过程可以总结成下面这样：

业务系统登录超时
  ↓
检查后端服务和数据库状态
  ↓
查看服务器磁盘和 Docker overlay
  ↓
发现 Docker 容器日志异常增大
  ↓
定位日志属于 MySQL 容器 /mes-hub-db
  ↓
排除 general_log 和 slow_query_log
  ↓
查看 MySQL 容器日志尾部
  ↓
发现 InnoDB 读文件错误持续刷屏
  ↓
查看 SHOW FULL PROCESSLIST
  ↓
发现线程 412 卡在 Opening tables 超过 18 小时
  ↓
确认线程编号与 InnoDB 错误日志编号一致
  ↓
判断不是正常迁移，而是异常查询线程卡死
  ↓
尝试 KILL，但线程未释放
  ↓
先备份数据
  ↓
重启 MySQL 容器
  ↓
异常线程清理，数据库和业务登录恢复正常

这次问题给我的一个提醒是：线上故障排查不能只看业务现象。登录超时只是表层表现，真正的问题可能在数据库线程、Docker 日志、磁盘资源甚至底层 I/O。

---

十一、后续怎么避免复发？

这类问题不能只靠“下次再排查”。更重要的是把预防措施补上。

1. 给 Docker 容器配置日志轮转

Docker 默认 json-file 日志如果不限制大小，容器一直刷日志就会导致日志无限增长。

建议在 docker-compose.yml 中配置：

logging:
  driver: json-file
  options:
    max-size: 200m
    max-file: "3"

含义是：

单个日志文件最大 200MB
最多保留 3 个日志文件

修改后通常需要重建容器才会生效：

docker compose up -d --force-recreate mes-hub-db

这个配置不只是 MySQL 容器要加，后端、前端、网关、定时任务等关键容器都应该统一加上。

---

2. 增加磁盘和日志告警

至少要监控这些内容：

根分区使用率
/var/lib/docker 目录大小
/var/lib/docker/containers 目录大小
单个容器日志文件大小
MySQL 容器日志增长速度

可以定期执行：

df -h

du -sh /var/lib/docker /var/lib/docker/containers /var/log 2>/dev/null

find /var/lib/docker/containers -name '*-json.log' -size +1G -ls

比较合理的告警策略是：

磁盘超过 80% 预警
磁盘超过 90% 严重告警
单个容器日志超过 1GB 告警
容器日志短时间快速增长告警

这样问题不会等到业务登录超时才被发现。

---

3. 定期巡检 MySQL 长时间线程

可以定期查看 MySQL 当前线程：

SHOW FULL PROCESSLIST;

重点关注这些情况：

Time 很长的非 Sleep 线程
卡在 Opening tables 的线程
卡在 Waiting for table metadata lock 的线程
卡在 Locked 的线程
来源 IP 异常的连接
和业务无关但长期运行的查询

也可以用 SQL 查超过 10 分钟的非 Sleep 线程：

SELECT
  ID, USER, HOST, DB, COMMAND, TIME, STATE, INFO
FROM INFORMATION_SCHEMA.PROCESSLIST
WHERE COMMAND != 'Sleep'
  AND TIME > 600
ORDER BY TIME DESC;

这类巡检对线上系统很有必要。很多数据库问题在真正影响业务之前，都会先表现为长线程、锁等待、连接堆积或慢查询。

---

4. 限制 MySQL 访问来源

这次异常线程来源是一个外部 IP：

112.124.239.53:31398

后续需要确认这个 IP 是否可信，比如是不是应用服务器、迁移服务器、数据库工具或者监控工具。

如果不是必要来源，就应该限制 MySQL 访问。

建议做到：

MySQL 不直接暴露公网
安全组只放行业务服务器 IP
数据库用户不要使用 % 作为 Host 范围
3306 端口通过防火墙或云安全组限制来源

可以先查看用户授权范围：

SELECT user, host FROM mysql.user;

如果存在：

mes_hub_user  %

就需要谨慎评估，最好改成固定业务服务器 IP。

---

5. 优化后端连接池和 SQL 超时

如果数据库线程卡住，后端连接池也可能受到影响。连接一直等待，接口自然就会超时。

以 HikariCP 为例，建议重点关注：

maximum-pool-size
connection-timeout
idle-timeout
max-lifetime
validation-timeout

治理目标是：

限制最大连接数，避免连接把数据库打满
设置连接获取超时，避免接口无限等待
设置连接最大生命周期，避免异常连接长期存在
设置连接校验超时，避免无效连接影响业务

同时，业务 SQL 也应该设置合理的执行超时，比如：

JDBC connectTimeout
JDBC socketTimeout
MyBatis defaultStatementTimeout
业务层接口超时控制

不要让一个 SQL 或一个数据库等待把整个登录链路拖死。

---

6. 固化备份和应急流程

这次处理里，“先备份，再重启”是比较稳妥的。

后续应该把它固化为 SOP：

业务登录超时
  ↓
确认后端服务是否正常
  ↓
确认 MySQL 容器是否正常
  ↓
查看磁盘和 Docker 日志占用
  ↓
查看 MySQL processlist
  ↓
判断是否为慢 SQL、锁等待、迁移任务或异常卡死线程
  ↓
尝试 KILL QUERY / KILL CONNECTION
  ↓
如果 KILL 不生效，先备份或做快照
  ↓
重启 MySQL 容器
  ↓
验证数据库和业务恢复
  ↓
补充日志轮转、监控告警和访问限制

线上问题最怕临时拍脑袋处理。尤其是数据库相关操作，重启之前最好有备份或快照兜底。

---

十二、总结

这次故障表面上是业务系统登录超时，最终定位到 MySQL Docker 容器日志异常增长。进一步排查发现，日志暴涨不是由数据迁移、general log 或 slow query log 引起的，而是 MySQL 中有一个线程长时间卡在 Opening tables，并持续触发 InnoDB 文件读取错误。

由于 KILL 无法及时释放该线程，最终在完成备份后重启 MySQL 容器，异常线程被清理，数据库和业务系统恢复正常。

这次问题可以总结成一句话：

登录超时不一定是登录接口的问题，容器日志、数据库线程、磁盘资源都可能是根因。

后续真正要做的不是记住某一条命令，而是把这一套防护补齐：

Docker 日志轮转，防止日志无限增长
磁盘和日志告警，提前发现异常
MySQL 长线程巡检，提前发现卡死线程
限制数据库访问来源，减少异常连接风险
连接池和 SQL 超时配置，避免请求无限等待
数据库备份和应急 SOP，保证故障可恢复

线上排查很多时候不是一下子找到答案，而是一步一步缩小范围。先看现象，再看资源，再看日志，再看线程，最后再处理根因。这个过程比单纯记命令更重要。