codis-proxy无故被shutdown

[hexusheng]

新部署的机器，zk 5台并且和codis-proxy，codis-server 部署在同一机器上，但是在么有任何压力，没有任何测试的情况下，codis-proxy和dashboard都异常退出了。
（codis是release 1.9.7版本）

dashboard日志：
2015/07/09 18:30:34 proxy.go:192: [info] mark_offline, check proxy status: proxy_21 zk: node does not exist
2015/07/09 18:30:34 proxy.go:194: [info] shutdown proxy successful
2015/07/09 18:30:44 proxy.go:192: [info] mark_offline, check proxy status: proxy_34 zk: node does not exist
2015/07/09 18:30:44 proxy.go:194: [info] shutdown proxy successful
2015/07/09 18:30:50 proxy.go:192: [info] mark_offline, check proxy status: proxy_35 zk: node does not exist
2015/07/09 18:30:50 proxy.go:194: [info] shutdown proxy successful
2015/07/09 18:30:58 proxy.go:192: [info] mark_offline, check proxy status: proxy_22 zk: node does not exist
2015/07/09 18:30:58 proxy.go:194: [info] shutdown proxy successful
2015/07/09 18:31:11 proxy.go:192: [info] mark_offline, check proxy status: proxy_23 zk: node does not exist
2015/07/09 18:31:11 proxy.go:194: [info] shutdown proxy successful
2015/07/09 18:31:20 proxy.go:192: [info] mark_offline, check proxy status: proxy_24 zk: node does not exist
2015/07/09 18:31:20 proxy.go:194: [info] shutdown proxy successful

2015/07/09 18:45:30 main.go:63: [fatal] ctrl-c or SIGTERM found, exit

codis-proxy-1日志：
2015/07/09 18:30:16 topology.go:155: [warning] topo event {Type:EventNodeDataChanged State:StateSyncConnected Path:/zk/codis/db_codis-cluster/proxy/proxy_21 Err:}
2015/07/09 18:30:16 topology.go:163: [warning] {Type:EventNodeDataChanged State:StateSyncConnected Path:/zk/codis/db_codis-cluster/proxy/proxy_21 Err:}
2015/07/09 18:30:16 topology.go:152: [fatal] session expired: {Type:EventNotWatching State:StateDisconnected Path:/zk/codis/db_codis-cluster/actions Err:zk: zookeeper is closing}

codis-proxy-2日志：
2015/07/09 18:30:54 topology.go:155: [warning] topo event {Type:EventNodeDataChanged State:StateSyncConnected Path:/zk/codis/db_codis-cluster/proxy/proxy_23 Err:}
2015/07/09 18:30:54 topology.go:163: [warning] {Type:EventNodeDataChanged State:StateSyncConnected Path:/zk/codis/db_codis-cluster/proxy/proxy_23 Err:}
2015/07/09 18:30:54 router.go:456: [fatal] suicide {Id:proxy_23 Addr:redis7-23:19000 LastEvent: LastEventTs:0 State:online Description: DebugVarAddr:redis7-23:11000 Pid:21414 StartAt:2015-07-09 13:41:06.496558669 +0800 CST}

zk所在的机器负载不高，不应该自己shutdown，请教下，这可能是啥原因呢？

[yangzhe1991]

2015/07/09 18:45:30 main.go:63: [fatal] ctrl-c or SIGTERM found, exit

这条至少说明不是程序自己退的，是外部有人kill掉了。

[hexusheng]

但是后来又有类似的情况codis-proxy退出了：
dashboard日志：
2015/07/16 14:36:03 proxy.go:192: [info] mark_offline, check proxy status: proxy_31 zk: node does not exist
2015/07/16 14:36:03 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:05 proxy.go:192: [info] mark_offline, check proxy status: proxy_29 zk: node does not exist
2015/07/16 14:36:05 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:07 proxy.go:192: [info] mark_offline, check proxy status: proxy_21 zk: node does not exist
2015/07/16 14:36:07 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:09 proxy.go:192: [info] mark_offline, check proxy status: proxy_22 zk: node does not exist
2015/07/16 14:36:09 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:11 proxy.go:192: [info] mark_offline, check proxy status: proxy_23 zk: node does not exist
2015/07/16 14:36:11 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:14 proxy.go:192: [info] mark_offline, check proxy status: proxy_34 zk: node does not exist
2015/07/16 14:36:14 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:16 proxy.go:192: [info] mark_offline, check proxy status: proxy_24 zk: node does not exist
2015/07/16 14:36:16 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:17 proxy.go:192: [info] mark_offline, check proxy status: proxy_25 zk: node does not exist
2015/07/16 14:36:17 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:19 proxy.go:192: [info] mark_offline, check proxy status: proxy_35 zk: node does not exist
2015/07/16 14:36:19 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:22 proxy.go:192: [info] mark_offline, check proxy status: proxy_26 zk: node does not exist
2015/07/16 14:36:22 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:24 proxy.go:192: [info] mark_offline, check proxy status: proxy_32 zk: node does not exist
2015/07/16 14:36:24 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:26 proxy.go:192: [info] mark_offline, check proxy status: proxy_27 zk: node does not exist
2015/07/16 14:36:26 proxy.go:194: [info] shutdown proxy successful
2015/07/16 14:36:29 proxy.go:192: [info] mark_offline, check proxy status: proxy_33 zk: node does not exist
2015/07/16 14:36:29 proxy.go:194: [info] shutdown proxy successful

proxy_33 日志：
2015/07/15 17:07:33 router.go:613: [warning] proxy_33 wait to be online
2015/07/16 14:36:20 topology.go:155: [warning] topo event {Type:EventNodeDataChanged State:StateSyncConnected Path:/zk/codis/db_codis-cluster/proxy/proxy_33 Err:}
2015/07/16 14:36:20 topology.go:163: [warning] {Type:EventNodeDataChanged State:StateSyncConnected Path:/zk/codis/db_codis-cluster/proxy/proxy_33 Err:}
2015/07/16 14:36:20 router.go:456: [fatal] suicide {Id:proxy_33 Addr:redis7-33:1900 LastEvent: LastEventTs:0 State:online Description: DebugVarAddr:redis7-33:11000 Pid:141554 StartAt:2015-07-15 17:06:15.149064733 +0800 CST}
2015/07/16 14:36:20 topology.go:152: [fatal] session expired: {Type:EventNotWatching State:StateDisconnected Path:/zk/codis/db_codis-cluster/actions Err:zk: zookeeper is closing}
2015/07/16 14:40:23 router.go:613: [warning] proxy_33 wait to be online

是因为codis-config发现zk异常，对应的proxy_33 节点不存在，然后将 codis-proxy shutdown了么？

[yangzhe1991]

dashboard有更早一些时候的log吗，直接看他关闭一堆proxy不确定是哪里的问题……
不过dashboard关闭proxy的原因应该只有两种，一种是手动关闭了，一种是迁移slot的时候proxy没有响应对应的action。应该和zk没有关系。

[hexusheng]

更早的日志就是这些了，15号的了，一共有13台 proxy，只有6台proxy处于online状态，我们没有做过手动迁移slot。
2015/07/15 16:51:36 dashboard.go:197: [info] dashboard listening on addr: 0.0.0.0:18087
2015/07/15 16:51:36 dashboard.go:180: [info] dashboard node created: /zk/codis/db_codis-cluster/dashboard {"addr": "0.0.0.0:18087", "pid": 35755}
2015/07/15 17:11:47 dashboard_apis.go:432: [warning] Some proxies may not stop cleanly: redis7-30:1900 redis7-20:19000
2015/07/15 17:11:55 dashboard_apis.go:432: [warning] Some proxies may not stop cleanly: redis7-20:19000 redis7-30:1900
2015/07/15 17:20:37 dashboard_apis.go:80: [error] dial tcp 192.168.7.29:6379: i/o timeout
2015/07/15 17:21:18 dashboard_apis.go:80: [error] dial tcp 192.168.7.29:6379: i/o timeout
2015/07/15 17:26:54 dashboard_apis.go:405: [warning] LOADING Redis is loading the dataset in memory
/usr/local/go/src/pkg/github.com/wandoulabs/codis/pkg/utils/redis_utils.go:119:
/usr/local/go/src/pkg/github.com/wandoulabs/codis/pkg/models/server_group.go:327:
2015/07/15 18:56:24 dashboard_apis.go:432: [warning] Some proxies may not stop cleanly: redis7-30:1900 redis7-20:19000

[yangzhe1991]

dashboard还会生成一个http的requestlog，看看那里面有没有/api/proxy 的post请求？因为能走到2015/07/16 14:36:03 proxy.go:192: [info] mark_offline, check proxy status: proxy_31 zk: node does not exist 这步而又没有proxies didn't responed 这个log的，理论上只可能是手动关闭了

[hexusheng]

筛了下那个时间点的日志，的确有/api/proxy请求，但是这个请求也看不出是online或者是offline操作吧，很奇怪，应该不会有别人操作的。顺便问下用的codis-proxy启动命令没啥问题吧，没用nohup：
../bin/codis-proxy -c ./config.ini -L ./log/codis-proxy.log --log-level=warn --cpu=15 --addr=0.0.0.0:1900 --http-addr=0.0.0.0:11000 &
：
[martini]2015/07/16 14:36:03 Started POST /api/proxy for 192.168.7.230:33382
[martini]2015/07/16 14:36:03 Started GET /api/proxy/list for 192.168.7.230:33384
[martini]2015/07/16 14:36:05 Started POST /api/proxy for 192.168.7.230:33387
[martini]2015/07/16 14:36:05 Started GET /api/proxy/list for 192.168.7.230:33388
[martini]2015/07/16 14:36:07 Started POST /api/proxy for 192.168.7.230:33390
[martini]2015/07/16 14:36:07 Started GET /api/proxy/list for 192.168.7.230:33391
[martini]2015/07/16 14:36:09 Started POST /api/proxy for 192.168.7.230:33393
[martini]2015/07/16 14:36:09 Started GET /api/proxy/list for 192.168.7.230:33394
[martini]2015/07/16 14:36:11 Started POST /api/proxy for 192.168.7.230:33397
[martini]2015/07/16 14:36:11 Started GET /api/proxy/list for 192.168.7.230:33398
[martini]2015/07/16 14:36:14 Started POST /api/proxy for 192.168.7.230:33400
[martini]2015/07/16 14:36:14 Started GET /api/proxy/list for 192.168.7.230:33401
[martini]2015/07/16 14:36:16 Started POST /api/proxy for 192.168.7.230:33403
[martini]2015/07/16 14:36:16 Started GET /api/proxy/list for 192.168.7.230:33404
[martini]2015/07/16 14:36:17 Started POST /api/proxy for 192.168.7.230:33406
[martini]2015/07/16 14:36:17 Started GET /api/proxy/list for 192.168.7.230:33407
[martini]2015/07/16 14:36:19 Started POST /api/proxy for 192.168.7.230:33410
[martini]2015/07/16 14:36:19 Started GET /api/proxy/list for 192.168.7.230:33411
[martini]2015/07/16 14:36:22 Started POST /api/proxy for 192.168.7.230:33414
[martini]2015/07/16 14:36:22 Started GET /api/proxy/list for 192.168.7.230:33416
[martini]2015/07/16 14:36:23 Started POST /api/proxy for 192.168.7.230:33418
[martini]2015/07/16 14:36:24 Started GET /api/proxy/list for 192.168.7.230:33419
[martini]2015/07/16 14:36:26 Started POST /api/proxy for 192.168.7.230:33421
[martini]2015/07/16 14:36:26 Started GET /api/proxy/list for 192.168.7.230:33422
[martini]2015/07/16 14:36:29 Started POST /api/proxy for 192.168.7.230:33426
[martini]2015/07/16 14:36:29 Started GET /api/proxy/list for 192.168.7.230:33427
[martini]2015/07/16 14:36:33 Started GET /api/proxy/list for 192.168.7.230:33432
[martini]2015/07/16 14:36:33 Started GET /api/proxy/list for 192.168.7.230:33433
[martini]2015/07/16 14:36:33 Started GET /api/proxy/list for 192.168.7.230:33435
[martini]2015/07/16 14:38:59 Started GET /api/proxy/list for 192.168.7.230:33600

[yangzhe1991]

这肯定是有人在操作对应的api吧。。
192.168.7.230 这个ip就是发出post请求的ip吧，查下这个机器对应的历史记录。

[hexusheng]

好的，感谢支持，我再注意观察，排查下。

[hexusheng]

压测时又发现有2台proxy退出了
proxy 26日志：
2015/07/22 08:55:15 topology.go:152: [fatal] session expired: {Type:EventNotWatching State:StateDisconnected Path:/zk/codis/db_codis-cluster/proxy/proxy_26 Err:zk: session has been expired by the server}

proxy 29日志：
2015/07/22 18:54:17 topology.go:152: [fatal] session expired: {Type:EventNotWatching State:StateDisconnected Path:/zk/codis/db_codis-cluster/proxy/proxy_29 Err:zk: session has been expired by the server}
2015/07/22 18:54:17 topology.go:152: [fatal] session expired: {Type:EventNotWatching State:StateDisconnected Path:/zk/codis/db_codis-cluster/actions Err:zk: session has been expired by the server}

dashboard只有这样的日志：
2015/07/22 14:56:23 dashboard.go:104: [warning] zk: connection closed

requests日志对应时间点没有/api/proxy 的post请求，应该不是人为调用api去关闭proxy的。测试过程中一直是2.5wOPS。

是不是真的因为proxy和zk连接有异常了导致？

[yangzhe1991]

这个log和前几天那个不一样。
这个是zk session expired了，说明当时proxy太卡，没有成功的在指定时间内发出心跳。

[Apache9]

有机器状态的监控嘛？当时机器的负载情况如何？
谢谢

[hexusheng]

机器状态有监控的，负载不高。一共16台机器，分别部署了8组codis-server（1 master+ 1 slave），其中抽出5台部署了zk，剩余机器中10台部署了codis-proxy，部署zk的机器上还部署了3台haproxy（每台haproxy后端只代理3台或4台codis-proxy），codis-proxy和zk，codis-proxy和haproxy 都是分开的。

[yangzhe1991]

proxy没有在timeout时间内发出心跳的原因一般是因为负载太高、比较卡，或者goroutine太多，一直调度不到刷心跳的goroutine。
proxy启动命令中有个--cpu，没有加这个参数的话默认只用两个，也会导致心跳发送失败的概率增大，还会导致CPU用不满所以性能受影响。你在压测的时候proxy机器的负载仍然不高，我有点怀疑是因为这个？需要确认下这个参数是否设置成了一个比较大的数（如果整个机器只有proxy进程，该参数设为CPU数即可）。
master/release1.9的代码里我也刚刚将这个参数的默认值改成CPU数。

[hexusheng]

@spinlock 因为我们部署上线，所以之前咨询过稳定的合适的版本，是1.9.7，2.0还没正式发布吧
@yangzhe1991 机器是20核，参数配置 --cpu=15
我再看看把 zk单独分开部署观察看看