{"action":"opened","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/19631","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/19631/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/19631/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/19631/events","html_url":"https://github.com/cockroachdb/cockroach/issues/19631","id":269452859,"number":19631,"title":"round robin restarting of a 3-node cluster","user":{"login":"mjibson","id":41181,"avatar_url":"https://avatars1.githubusercontent.com/u/41181?v=4","gravatar_id":"","url":"https://api.github.com/users/mjibson","html_url":"https://github.com/mjibson","followers_url":"https://api.github.com/users/mjibson/followers","following_url":"https://api.github.com/users/mjibson/following{/other_user}","gists_url":"https://api.github.com/users/mjibson/gists{/gist_id}","starred_url":"https://api.github.com/users/mjibson/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mjibson/subscriptions","organizations_url":"https://api.github.com/users/mjibson/orgs","repos_url":"https://api.github.com/users/mjibson/repos","events_url":"https://api.github.com/users/mjibson/events{/privacy}","received_events_url":"https://api.github.com/users/mjibson/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2017-10-30T00:36:12Z","updated_at":"2017-10-30T00:36:12Z","closed_at":null,"author_association":"OWNER","body":"3 nodes in the cluster running an GCE 2-cpu preemptible instances. Running the k8s statefulset yaml on version:\r\n\r\n```\r\nBuild Tag:    v1.2-alpha.20170901-1172-g99a04b6\r\nBuild Time:   2017/10/29 21:59:18\r\nDistribution: CCL\r\nPlatform:     linux amd64\r\nGo Version:   go1.9\r\nC Compiler:   gcc 6.3.0\r\nBuild SHA-1:  99a04b6afb79a56f7ef3e1f1b38e3ad084c5c71d\r\nBuild Type:   release-gnu\r\n```\r\n\r\nEvery few minutes a different node restarts, although none at the same time (that I've seen). I can't see any obvious error in the logs. The k8s RESTARTS counter is at 0 for the pods, but the AGE counter rarely gets above 5m. Here's an example log of one of the nodes, ending at the time of the restart.\r\n\r\n```\r\nW171029 22:18:56.504098 79 storage/store.go:3677  [n3,s3] handle raft ready: 0.6s [processed=0]\r\nW171029 22:18:56.504179 80 storage/store.go:3677  [n3,s3] handle raft ready: 0.6s [processed=0]\r\nW171029 22:18:56.504256 81 storage/store.go:3677  [n3,s3] handle raft ready: 0.6s [processed=0]\r\nW171029 22:18:56.505425 77 storage/store.go:3677  [n3,s3] handle raft ready: 0.6s [processed=0]\r\nI171029 22:18:57.225555 146 server/status/runtime.go:219  [n3] runtime stats: 1.1 GiB RSS, 191 goroutines, 75 MiB/43 MiB/152 MiB GO alloc/idle/total, 754 MiB/927 MiB CGO alloc/total, 22628.57cgo/sec, 1.52/0.06 %(u/s)time, 0.00 %gc (8x)\r\nI171029 22:18:57.274507 144 gossip/gossip.go:486  [n3] gossip status (ok, 3 nodes)\r\ngossip client (1/3 cur/max conns)\r\n  2: cockroachdb-1.cockroachdb.default.svc.cluster.local:26257 (44s: infos 98/272 sent/received, bytes 51141B/60311B sent/received)\r\ngossip server (0/3 cur/max conns, infos 332/508 sent/received, bytes 121183B/202208B sent/received)\r\nI171029 22:18:57.701755 143 storage/store.go:4166  [n3,s3] temporarily disabling rebalances because RaftLogSelfBehindCount=3003\r\nW171029 22:18:58.466281 77 storage/store.go:3677  [n3,s3] handle raft ready: 0.5s [processed=0]\r\nW171029 22:18:58.467264 114 storage/store.go:3677  [n3,s3] handle raft ready: 0.5s [processed=0]\r\nW171029 22:18:58.467435 121 storage/store.go:3677  [n3,s3] handle raft ready: 0.5s [processed=0]\r\nW171029 22:18:58.469871 122 storage/store.go:3677  [n3,s3] handle raft ready: 0.5s [processed=0]\r\nW171029 22:18:58.470204 81 storage/store.go:3677  [n3,s3] handle raft ready: 0.5s [processed=0]\r\nI171029 22:18:59.327850 115 storage/replica_proposal.go:475  [n3,s3,r783/2:/Table/51/11/1{4/19/…-5/50/…}] new range lease repl=(n3,s3):2 start=1509315538.384237545,0 epo=203 pro=1509315538.384242188,0 following repl=(n2,s2):3 start=1509314016.351547562,0 epo=191 pro=1509314016.351551418,0\r\nI171029 22:18:59.378455 115 storage/replica_proposal.go:475  [n3,s3,r900/2:/Table/51/12/1{4/55/…-6/22/…}] new range lease repl=(n3,s3):2 start=1509313972.326724504,0 epo=203 pro=1509315538.556808667,0 following repl=(n3,s3):2 start=1509313972.326724504,0 epo=190 pro=1509313972.326736965,0\r\nI171029 22:18:59.448177 115 storage/replica_proposal.go:475  [n3,s3,r722/2:/Table/51/10/1{4/44/…-6/8/1…}] new range lease repl=(n3,s3):2 start=1509313971.543979738,0 epo=203 pro=1509315537.953005465,0 following repl=(n3,s3):2 start=1509313971.543979738,0 epo=190 pro=1509313971.543983907,0\r\nI171029 22:18:59.456742 115 storage/replica_proposal.go:475  [n3,s3,r1016/2:/Table/51/13/1{4/38/…-6/6/8…}] new range lease repl=(n3,s3):2 start=1509313972.420855479,0 epo=203 pro=1509315538.923755808,0 following repl=(n3,s3):2 start=1509313972.420855479,0 epo=190 pro=1509313972.420859934,0\r\nW171029 22:19:04.816586 115 storage/store.go:3677  [n3,s3] handle raft ready: 0.6s [processed=0]\r\nI171029 22:19:07.397643 146 server/status/runtime.go:219  [n3] runtime stats: 1.1 GiB RSS, 170 goroutines, 112 MiB/20 MiB/156 MiB GO alloc/idle/total, 763 MiB/929 MiB CGO alloc/total, 103172.29cgo/sec, 1.56/0.10 %(u/s)time, 0.00 %gc (5x)\r\nI171029 22:19:08.048866 143 storage/store.go:4166  [n3,s3] temporarily disabling rebalances because RaftLogSelfBehindCount=3003\r\nI171029 22:19:09.115988 119 storage/replica_proposal.go:475  [n3,s3,r941/3:/Table/51/12/5{1/20/…-2/27/…}] new range lease repl=(n3,s3):3 start=1509315548.796519833,0 epo=203 pro=1509315548.796524982,0 following repl=(n1,s1):1 start=1509315179.203821206,0 epo=207 pro=1509315474.320288672,0\r\nI171029 22:19:09.131065 80 storage/replica_proposal.go:475  [n3,s3,r1038/2:/Table/51/13/52/{53/2…-73/2…}] new range lease repl=(n3,s3):2 start=1509315549.092869628,0 epo=203 pro=1509315549.092873896,0 following repl=(n1,s1):1 start=1509314178.880292331,0 epo=196 pro=1509314178.880296998,0\r\nI171029 22:19:09.134222 76 storage/replica_proposal.go:475  [n3,s3,r1382/2:/Table/51/13/5{1/38/…-2/53/…}] new range lease repl=(n3,s3):2 start=1509315549.089263180,0 epo=203 pro=1509315549.089266899,0 following repl=(n1,s1):1 start=1509315179.271141254,0 epo=207 pro=1509315474.445223583,0\r\nW171029 22:19:11.003491 76 storage/store.go:3677  [n3,s3] handle raft ready: 0.8s [processed=0]\r\nW171029 22:19:11.091239 115 storage/store.go:3677  [n3,s3] handle raft ready: 0.9s [processed=0]\r\nW171029 22:19:11.092107 122 storage/store.go:3677  [n3,s3] handle raft ready: 0.9s [processed=0]\r\nW171029 22:19:11.092400 118 storage/store.go:3677  [n3,s3] handle raft ready: 0.9s [processed=0]\r\n```\r\n\r\nMost of the scrollback is the same. 30GB total size, ~1k ranges. Very few reads, big batches of inserts every few hours (but no writes inbetween those).\r\n\r\nI'm not sure what else to do to debug this. The admin UI is publicly viewable, can provide the address on request."}}
{"actor":{"display_login":"mjibson"}}