记一次服务器宕机 - A Record of a Server Downtime

Posted on In , Views: Word count in article: 327 Reading time ≈ 1 mins.

起来一看服务器 CPU 100%…

起因

凌晨推了个 Flask 后端上去，1h 内没问题，下午一看 CPU 100%，ssh 都上不去

负载曲线

负载和 CPU 使用率都很高，12:20 后阿里云的统计数据都断掉了，我 16 点左右重启 server 又一切正常，一开始怀疑是不是 Flask 后端的 bug，有 web shell 被人打了，后来翻了下 nginx 的 access log 和 error log，都没有什么异常，公网流量也没有异常，但是 Established 的连接数一直从 70 增加到 790 左右，这段时间也是 CPU 使用率快速上升的时间段，感觉是因为系统宕机导致新的请求到来无法响应，导致 Established 的连接数堆积

网络流量

疑似原因

没去复现问题，看了一下午 log，在 syslog 中找到了这些:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
Jul 22 06:27:46 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Daily apt upgrade and clean activities...
Jul 22 06:30:54 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: session-37572.scope: Deactivated successfully.
Jul 22 06:31:13 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: session-37572.scope: Consumed 2.641s CPU time.
Jul 22 06:31:49 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Watchdog timeout (limit 5min)!
Jul 22 06:32:23 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Killing process 2716955 (snapd) with signal SIGABRT.
Jul 22 06:33:30 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: State 'stop-watchdog' timed out. Killing.
Jul 22 06:33:37 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Killing process 2716955 (snapd) with signal SIGKILL.
Jul 22 06:33:44 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Main process exited, code=killed, status=9/KILL
Jul 22 06:33:51 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'watchdog'.
Jul 22 06:33:59 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Consumed 6min 44.867s CPU time.
Jul 22 06:34:07 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 2.
Jul 22 06:34:14 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:34:24 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Consumed 6min 44.867s CPU time.
Jul 22 06:34:33 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:34:40 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:34:48 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:34:57 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:35:13 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 3.
Jul 22 06:35:25 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:35:35 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:35:47 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:36:07 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:36:22 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:36:31 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 4.
Jul 22 06:36:48 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:37:05 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:37:26 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:37:47 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:38:09 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:38:29 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 5.
Jul 22 06:38:49 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:39:09 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:39:29 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:39:54 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:40:13 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:40:34 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 6.
Jul 22 06:40:52 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:41:06 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:41:26 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:41:39 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:41:57 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:42:27 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 7.
Jul 22 06:42:47 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:43:08 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:43:34 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:43:56 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:44:18 iZbp1bgbzs4hpmh6uo1879Z CRON[3256334]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 22 06:44:29 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:45:01 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 8.
Jul 22 06:45:34 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:46:02 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:46:36 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:46:57 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:47:15 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:47:46 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 9.
Jul 22 06:48:09 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:48:25 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:48:49 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:49:12 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:49:35 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:49:53 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 10.
Jul 22 06:50:19 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:50:53 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:51:25 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:52:08 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:52:48 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:53:31 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 11.
Jul 22 06:53:55 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:54:05 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:54:22 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:54:32 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:54:46 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:54:59 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 12.
Jul 22 06:55:09 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:55:19 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:55:32 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:55:45 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:55:55 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:56:10 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 13.
Jul 22 06:56:28 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:56:59 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:57:10 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:57:24 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:57:33 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:57:46 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 14.
Jul 22 06:57:56 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:58:06 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:58:18 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Daily man-db regeneration...
Jul 22 06:58:29 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:58:40 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:58:49 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 06:58:59 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 15.
Jul 22 06:59:09 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 06:59:20 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 06:59:32 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 06:59:41 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 06:59:49 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 07:00:02 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 16.
Jul 22 07:00:10 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 07:00:24 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 07:00:33 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 07:00:56 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 07:01:14 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 07:01:26 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 17.
Jul 22 07:01:35 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 07:01:43 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 07:01:54 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 07:02:18 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 07:02:53 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 07:03:26 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 18.
Jul 22 07:03:48 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 07:04:25 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 07:04:40 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 07:04:51 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 07:05:12 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 07:05:37 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 19.
...
Jul 22 11:56:37 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 11:57:21 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 129.
Jul 22 11:57:47 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 11:58:15 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 11:59:00 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 12:00:37 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 12:01:28 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 12:02:17 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 130.
Jul 22 12:02:54 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 12:04:30 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 12:05:42 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 12:06:50 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 12:08:50 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 12:09:45 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 131.
Jul 22 12:10:06 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Stopped Snap Daemon.
Jul 22 12:10:37 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Snap Daemon...
Jul 22 12:11:02 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: start operation timed out. Terminating.
Jul 22 12:11:14 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Failed with result 'timeout'.
Jul 22 12:11:25 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Failed to start Snap Daemon.
Jul 22 12:11:37 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: snapd.service: Scheduled restart job, restart counter is at 132.
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd-modules-load[408]: Inserted module 'msr'
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Mounting FUSE Control File System...
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Mounting Kernel Configuration File System...
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Device-Mapper Multipath Device Controller...
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Flush Journal to Persistent Storage...
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Load/Save Random Seed...
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Apply Kernel Variables...
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Starting Create System Users...
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Mounted FUSE Control File System.
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Mounted Kernel Configuration File System.
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z systemd[1]: Finished Load/Save Random Seed.
Jul 22 16:19:16 iZbp1bgbzs4hpmh6uo1879Z multipathd[429]: --------start up--------

apt-daily-upgrade 没有看到 finish 的 log，但从 apt 的相关 log 来看是没有装什么包，主要的 log 还是 snapd 的自动重启，是由于一开始 watchdog timeout 了，不明原因，但是好像网上有类似 issue

解决方案

于是先把 snapd 禁用掉自动 refresh

1
2
3
4
sudo snap refresh --hold=forever
snap refresh --time
sudo systemctl disable --now snap.certbot.renew.timer
sudo snap stop --disable lxd

恢复方法

1
2
3
sudo snap refresh --unhold
sudo snap start --enable lxd
sudo systemctl enable --now snap.certbot.renew.timer

其实系统版本有点老了，但是没什么磁盘空间，就不更新系统了。。