Postmortem: UPS 测试导致系统停机故障的事后回顾

摘要

事故影响

由于 UPS 测试触发了系统停机，导致 delphij.net 部分服务停止了约40分钟。服务从 2023-01-16 15:46:20 开始受到影响，至 16:26:55 完全恢复。如果服务未能及时修复，潜在地将会进一步影响包括权威DNS（有多个独立的冗余，但依赖于持续的数据更新）在内的一些其他关键服务。

问题根源

在测试时对于 CyberPower UPS 测试特性的认识不足导致电池电量消耗至临界值，由于对 nut 的配置未考虑这种情况直接将服务器关闭，这使得必须亲自到机房才能完成服务的恢复。

故障背景

nut 是在2023年1月13日开始近采用的，用来替换配合 APC UPS 使用的 apcupsd 的 UPS 管理软件。与 apcupsd 类似，它也提供了在电池电量低于警戒线时关闭系统的功能。

nut 提供的针对 CyberPower SX650G UPS 的驱动中提供了 test.battery.start.deep 指令，对于大部分其他 UPS 而言，该指令的作用是将 UPS 的电池消耗到 low battery 水平之后再恢复从交流电充电。

为了验证在使用 nut 时系统仍然可以像在使用 apcupsd 时那样正确关闭和重启系统，于2023年1月16日对其一系列 UPS 和 nut 特性进行了测试。

问题根源及触发过程

此测试过程中，对于 UPS 的深度电池测试导致电池的电量低于了此前设置的 20% 水平，而 UPS 的控制器并未如其他 UPS 那样在此时恢复从交流电供电进行充电，并且此时 nut 的 upsmon 由于收到了电池电量过低的信号，如配置那样地开始了关机过程。

影响

本次故障导致 delphij.net 部分服务从 2023-01-16 15:46:20 开始受到影响，直至 16:26:55 完全恢复，共计约40分钟。由于受影响的服务器提供了到某些其他服务的隧道，导致家中的网络也受到了影响。

教训

不应过于信赖消费级 UPS 控制器和开源软件的兼容性，此类测试应该在可控且非生产环境中进行。
在进行此类可能导致停机的测试时，应提前设计方案，以非破坏性的命令替换真正的 poweroff 命令。

较顺利的部分

机房开车距离约为30分钟，在发现问题之后迅速做出了去机房的决定减少了停机时间。
UPS 和服务器硬件没有因为断电导致损坏。

不顺利的部分

操作人员到达机房时，UPS 在持续报警，为了迅速恢复服务对其进行了 power cycle （按住开关2秒关闭之后再重新启动），因此并不知道该 UPS 是否在剩余电量达到某一阈值之后正确地自动恢复了供电。
UPS 在操作人员到达机房时，其电池已经消耗到了接近5%的水平。这使得首次启动时 upsmon 立即触发了再次关闭。
机房开车距离约为30分钟，由于情况复杂必须去机房而不是依赖机房本地的远程操作，因此导致了停机时间的延长。

幸运的部分

测试发生在假日，因此有比较充足的时间去进行处理。
由于测试是在白天进行，并且由于是在测试的进行过程中，发生问题时得以立即发现并采取措施。
测试之前已经完成了 nut_exporter 的部署，因此获得了较为完整的放电特性数据，知道了 UPS 从 100% 放电到 20% 的时间约为933秒，其中前12%的放电曲线比较陡峭，后续的变化率则变得较缓。根据UPS的计算，后续20%的电量大约可支持300秒左右，而根据前面的放电速度较为保守的估计则是240秒左右，这个时长远远超过了该系统关机所需的时间（作为参考，服务器关闭前最后一次录得的电池电量数据是19%，虽然实际最终剩余的电量一定会比这个少，但至少说明及时关机来保护数据的目的是可以达到的）
获得了 UPS 从 6% 充电到 100% 时需要大约 6 小时 45 分钟的数据。

总结、后续及其他发现

试验未能达到预想的测试 UPS 电池深度测试的目标，操作人员到达机房时的首要任务是恢复服务，因此选择破坏了部分现场并导致无法获得完整的试验数据；此外，测试未能证明在实际发生长时间断电之后在供电恢复时，系统是否能在没有人在现场手工干预的情况下重新启动，这需要在后续的测试中加以解决。

作为一款消费级的产品，CyberPower SX650G UPS 的 USB 接口协议，以及其控制器的 datasheet 不易获得，这意味着想要确切了解其指令行为并不容易。nut 提供的开源驱动中，也只是简单地实现了相关接口，对于其行为是否能够达到与文档或代码预期的全部目标并无充分的测试，这并不是开源项目的责任，但作为用户应该对此有所认知，并在使用时考虑这一因素。

测试证明此前配置的关机的部分能够在需要时正确触发，并且工作正常（尽管这本身导致了服务中断）。

配置的数据采集系统在放电测试过程中记录了放电数据，证实了目前配置能够达到系统对于后备电源的需要，而这些是最初打算进行这些测试想要达到的核心目标，故而可以认为此次试验的主要目的达成了。

后续计划

关机应由命令改为脚本，并考虑 UPS 的交流电决定是否真的实施关闭系统的操作。
在生产环境中进行测试时，应更好地遵守一系列原则，例如：a) 不要在生产环境中进行测试，b) 必须进行此类测试时，应提前设计方案，以非破坏性的命令替代实际的破坏性操作。
需要对真实的断电场景进行单独的测试。
对 nut 的 LOWBATT 事件处理部分进行改进，加入对于是否正在充电的处理：只有在处于 LOWBATT 并且电池处于放电状态时的情形，才应触发 shutdown。

时间线(所有时间为当地，即太平洋标准时间PST，或协调世界时UTC -08:00)

2023-01-13 完成了UPS替换操作并部署了 nut。
2023-01-14 进行了首次 test.battery.start.deep 测试，注意到它在电池达到 20% 和 10% 时并未认定为测试完成并恢复充电。在耗电达到 8% 时使用 test.battery.stop 终止了测试。
2023-01-14 部署了 upsmon 配置，令系统在 UPS 达到 low battery 时触发 shutdown。
2023-01-16 15:29:31 进行了一次 test.battery.start.quick 测试，正常触发了 ON BATTERY 和 ON AC 事件并收到了邮件。
2023-01-16 15:30:30 开始 test.battery.start.deep 测试，由于之前有1月14日的教训，以脚本循环读取电池余量，并在 Grafana 上打开相应的面板观察其他数据。
2023-01-16 15:30:37 upsmon 检测到 UPS 正在以电池供电，正确触发了 ON BATTERY 报警并收到了邮件。此后电池电量从 100% 逐步减少到 20%。
2023-01-16 15:46:20 电池电量达到了20%，upsmon 触发了 LOWBATT 事件并开始 shutdown 过程。由于此时已经正确配置了 shutdown 脚本，因此该脚本被执行。<故障开始>
2023-01-16 15:46:40 操作人员注意到控制台报警，同时 ssh 会话中断，发现服务器仍然可以 ping 到但 ssh 已经不再响应。<检测到故障的时刻>
2023-01-16 16:23:22 操作人员到达机房并手工启动机器。
2023-01-16 16:23:33 服务器发现 UPS 剩余电量低，触发了 LOWBATT 事件并再次开始 shutdown 过程。
2023-01-16 16:25:58 再次启动进入单用户模式，禁用 nut_upsmon 并再次启动。
2023-01-16 16:26:55 所有服务正常启动，故障成功缓解<影响结束><故障结束>