问题
在开发可视化机器学习平台时，集成的FastRCNN实验一直跑不到结束就会出错。有时候是在下载基础模型以及代码包时出错，有时候在train结束后向predict传递artifacts出错。
过程
首先这个问题出现在局域网内，处于开发环境，因此ceph没有做高可用的部署。其次，ceph是用rook这个项目部署在k8s集群中的。
最后，在使用argo做机器学习的资源调度时，会出现大的数据资源下载和转移出现错误。具体表现为：大量数据下载会出现connectiion refused,日志如下：
2019-10-25 02:35:24 (20.1 MB/s) - Connection closed at byte 528482304. Retrying.
--2019-10-25 02:35:25-- (try: 2) http://rook-ceph-rgw-my-store.rook-ceph/workflow-storage/tho6wHm0UmZeZYbfWBv5lkOZ576838763
Connecting to rook-ceph-rgw-my-store.rook-ceph (rook-ceph-rgw-my-store.rook-ceph)|10.43.126.166|:80... failed: Connection refused.
Resolving rook-ceph-rgw-my-store.rook-ceph (rook-ceph-rgw-my-store.rook-ceph)... 10.43.126.166
Connecting to rook-ceph-rgw-my-store.rook-ceph (rook-ceph-rgw-my-store.rook-ceph)|10.43.126.166|:80... failed: Connection refused.
大量数据上传时也会中断，导致argo无法调用下一步：
日志如下：
NAME custom-workflow-43-6rhlb.api-train-faster-1699
TYPE Pod
PHASE Error
MESSAGE failed to save outputs: timed out waiting for the condition
START TIME 2019-10-24T06:15:56Z
END TIME 2019-10-24T06:30:34Z
DURATION 14:38 min
这里可能是网络问题，argo的问题或者是ceph的问题。但是当数据量不大的时候不会出现错误。因此检查ceph是否正常
~ » kubectl -n rook-ceph get pods
NAME READY STATUS RESTARTS AGE
csi-cephfsplugin-964zm 3/3 Running 27 46d
csi-cephfsplugin-dxnbg 3/3 Running 12 46d
csi-cephfsplugin-provisioner-b66d48bc8-fglq9 4/4 Running 0 12d
csi-cephfsplugin-provisioner-b66d48bc8-x67pd 4/4 Running 0 12d
csi-rbdplugin-5fs2x 3/3 Running 27 46d
csi-rbdplugin-bddlt 3/3 Running 12 46d
csi-rbdplugin-provisioner-95dd85d6-7kc4c 5/5 Running 0 12d
csi-rbdplugin-provisioner-95dd85d6-mpjtj 5/5 Running 0 12d
rook-ceph-agent-fs4xq 1/1 Running 9 46d
rook-ceph-agent-wx6r4 1/1 Running 4 46d
rook-ceph-mds-myfs-a-774974c8c4-xt2ls 1/1 Running 0 12d
rook-ceph-mds-myfs-b-748d7d7f7d-wftt5 1/1 Running 0 12d
rook-ceph-mgr-a-5f54d44c98-57qcb 1/1 Running 0 12d
rook-ceph-mon-a-6f9fbfc99d-lmb6c 1/1 Running 0 17d
rook-ceph-operator-6f556bcbff-glvt6 1/1 Running 0 12d
rook-ceph-osd-0-7c489dc87b-wkt7x 1/1 Running 0 17d
rook-ceph-osd-1-86cc67cc45-25h4q 1/1 Running 0 12d
rook-ceph-osd-prepare-worknode1-xnmpw 0/1 Completed 0 12d
rook-ceph-rgw-my-store-a-66b7d8cc9d-vrhkm 1/1 Running 65 12d
rook-ceph-tools-5f5dc75fd5-52jbj 1/1 Running 0 12d
rook-discover-g95ws 1/1 Running 6 46d
rook-discover-vs5fs 1/1 Running 13 46d
发现ceph rgw重启了65次，这个肯定是不正常的。查看ceph rgw的日志:
$ kubectl -n rook-ceph logs -p rook-ceph-rgw-my-store-a-66b7d8cc9d-vrhkm
# 截取了一部分日志
debug 2019-10-25 02:35:13.473 7f4880b98700 1 ====== starting new request req=0x55aa678c48e0 =====
debug 2019-10-25 02:35:14.549 7f4880b98700 0 ERROR: client_io->complete_request() returned Broken pipe
debug 2019-10-25 02:35:14.549 7f4880b98700 1 ====== req done req=0x55aa678c48e0 op status=0 http_status=200 latency=1.076s ======
debug 2019-10-25 02:35:19.949 7f48e345d700 1 ====== starting new request req=0x55aa54a488e0 =====
debug 2019-10-25 02:35:19.949 7f48e345d700 1 ====== req done req=0x55aa54a488e0 op status=0 http_status=404 latency=0s ======
在我的理解中broken pipe一般出现在向已关闭的连接中写入数据时，会出现这个问题。但是通过日志可以发现，出现broken pipe的错误之后，rgw仍然是在处理请求的，但是部分请求的latency很高。因此这里的broken pipe是表示着rgw开始出现一些异常情况，但不是pod重启的直接原因。
真正导致rgw被杀死的原因是因为rgw进程收到了sigterm信号，然后进程被杀死。
debug 2019-10-25 02:35:24.525 7f494c52f700 -1 received signal: Terminated from Kernel ( Could be generated by pthread_kill(), raise(), abort(), alarm() ) UID: 0
debug 2019-10-25 02:35:24.525 7f494c52f700 1 handle_sigterm
debug 2019-10-25 02:35:24.525 7f494c52f700 1 handle_sigterm set alarm for 120
debug 2019-10-25 02:35:24.525 7f4962116780 -1 shutting down
debug 2019-10-25 02:35:24.629 7f488cbb0700 0 iterate_obj() failed with -9
使用kubectl describe查看pod的event:
Events:
Type Reason Age From Message
---- ------ ---- ---- -------
Normal Killing 15m (x65 over 12d) kubelet, worknode1 Container rgw failed liveness probe, will be restarted
Warning Unhealthy 15m (x249 over 12d) kubelet, worknode1 Liveness probe failed: Get http://10.42.2.44:80/: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
Normal Pulled 15m (x66 over 12d) kubelet, worknode1 Container image "ceph/ceph:v14.2.2-20190826" already present on machine
Normal Created 15m (x66 over 12d) kubelet, worknode1 Created container rgw
Normal Started 15m (x66 over 12d) kubelet, worknode1 Started container rgw
这里才是真正的重启原因，kubelet检查pod是否存活，但是请求超时了。意味pods出现的故障，因此杀死了pod并重启。
pod的liveness设置:
Liveness: http-get http://:80/ delay=10s timeout=1s period=10s #success=1 #failure=3
k8s的liveness机制是检查pod中应用程序存活状态并在出错后自动重启的一种机制。提供了三种方式：
- 在容器内执行命令，如果执行成功，则表示容器是存活并且健康的。否则就重启容器使得应用程序恢复正常。
- 使用http请求检查，如果返回的状态码是200则表示正常，否则表示失败。
- 使用tcp连接检查，如果kubelet可以打开指定端口的socket连接，则表示正常，否则表示失败。
在这个场景下出现Warning Unhealthy 15m (x249 over 12d) kubelet, worknode1 Liveness probe failed: Get http://10.42.2.44:80/: net/http: request canceled (Client.Timeout exceeded while awaiting headers)，表示kubelet使用http get检查pod的80端口，但是这个请求却超时了。因此杀死了容器并重启，导致大文件(700MB以上)上传/下载失败。
这里kubelet检查的是http://10.42.2.44:80这个地址，我们回过头看一下argo那边的报错信息，Connecting to rook-ceph-rgw-my-store.rook-ceph (rook-ceph-rgw-my-store.rook-ceph)|10.43.126.166|:80... failed: Connection refused.。都是80端口，当然这里千万不能被ip地址误导了，10.42.2.44是pod的ip地址，10.43.126.166是service的ip地址，我们可以验证一下:
~ » kubectl -n rook-ceph get svc
NAME TYPE CLUSTER-IP EXTERNAL-IP PORT(S) AGE
rook-ceph-rgw-my-store ClusterIP 10.43.126.166 <none> 80/TCP 46d
然后再结合之前debug 2019-10-25 02:35:14.549 7f4880b98700 1 ====== req done req=0x55aa678c48e0 op status=0 http_status=200 latency=1.076s ======这条日志，latency已经超过了1s，而kubelet的liveness超时时间是1s。
现在基本可以得出以下异常流程:
- 因为某些原因，导致rgw出现broken pipe的出错，并且部分请求的lantency时间大大提高。
- kubelet周期性的对rgw做liveness的检查，并且检查的http就是rgw的80端口，这个端口因为上面的原因导致lantency超过了1s，而liveness检查的timeout只有1s。因此kubelet认为该pod不健康，选择重启。
- kubelet向rgw发送了
sigterm信号，rgw关闭进程，pod重启。
猜测可能造成这个问题的原因:
- ceph所在机器的性能不够，导致响应请求出现问题。
- 局域网的网络问题，因为内部的最高带宽只有10MB/s，但是局域网内的设备很多，网络这部分导致了瓶颈。
关于机器性能的问题，我认为是可以排除的，因为机器性能本身很好，并且开发环境几乎没有请求量，接下来就是验证是因为网络问题导致瓶颈，造成部分接口延迟过高被杀死。
为了验证这个猜想，假设这里有三台机器A,B,C，组成了一个k8s集群，ceph是部署在k8s之上的。在A之上，我用dd命令产生一个40G的大文件，然后在B之上使用wget下载。然后在C上面观察ping的延迟是否上升。
A:
$ dd if=/dev/zero of=test bs=1M count=0 seek=40000
$ python -m SimpleHTTPServer 8999
B:
$ wget http://192.168.50.37:8999/test
--2019-10-25 14:18:30-- http://192.168.50.37:8999/test
正在连接 192.168.50.37:8999... 已连接。
已发出 HTTP 请求，正在等待回应... 200 OK
长度： 41943040000 (39G) [application/octet-stream]
正在保存至: “test”
test 3%[==> ] 1.54G 11.1MB/s 剩余 73m 5s
C:
$ ping 192.168.50.37
PING 192.168.50.37 (192.168.50.37) 56(84) bytes of data.
64 bytes from 192.168.50.37: icmp_seq=1 ttl=64 time=0.384 ms
64 bytes from 192.168.50.37: icmp_seq=2 ttl=64 time=0.373 ms
64 bytes from 192.168.50.37: icmp_seq=3 ttl=64 time=0.336 ms
64 bytes from 192.168.50.37: icmp_seq=4 ttl=64 time=4.90 ms
64 bytes from 192.168.50.37: icmp_seq=5 ttl=64 time=1.18 ms
64 bytes from 192.168.50.37: icmp_seq=6 ttl=64 time=7.74 ms
64 bytes from 192.168.50.37: icmp_seq=7 ttl=64 time=3.51 ms
64 bytes from 192.168.50.37: icmp_seq=8 ttl=64 time=6.66 ms
64 bytes from 192.168.50.37: icmp_seq=9 ttl=64 time=6.31 ms
网络延迟增加的还是很明显的。
这时候使用argo开始一个新的机器学习的实验，但是这个实验的数据量较小，在之前的使用中都没有问题。结果确实出现了问题：
2019-10-25 06:21:04 (8.10 MB/s) - Connection closed at byte 136314880. Retrying.
--2019-10-25 06:21:05-- (try: 2) http://rook-ceph-rgw-my-store.rook-ceph/workflow-storage/maC8Om6Y3QbSJxSTT9x82rp8908272441
Connecting to rook-ceph-rgw-my-store.rook-ceph (rook-ceph-rgw-my-store.rook-ceph)|10.43.126.166|:80... failed: Connection refused.
Resolving rook-ceph-rgw-my-store.rook-ceph (rook-ceph-rgw-my-store.rook-ceph)... 10.43.126.166
Connecting to rook-ceph-rgw-my-store.rook-ceph (rook-ceph-rgw-my-store.rook-ceph)|10.43.126.166|:80... failed: Connection refused.
那么为了有对照实验，将下载关闭，重新做这个机器学习的实验，结果正常。
解决方法
因为缺少了对ceph这块源代码的研究，上面的结论并不一定正确。但是可以大概得出如何解决，可以先尝试将liveness检测的timeout时间增加。
kubectl -n rook-ceph edit deployment rook-ceph-rgw-my-store-a
把liveness的timeout时间调成5s，这样就解决了这个问题。