{"action":"created","issue":{"url":"https://api.github.com/repos/deis/deis/issues/3303","labels_url":"https://api.github.com/repos/deis/deis/issues/3303/labels{/name}","comments_url":"https://api.github.com/repos/deis/deis/issues/3303/comments","events_url":"https://api.github.com/repos/deis/deis/issues/3303/events","html_url":"https://github.com/deis/deis/issues/3303","id":61772712,"number":3303,"title":"Gateway & Builder restarts","user":{"login":"dylanz","id":13274,"avatar_url":"https://avatars.githubusercontent.com/u/13274?v=3","gravatar_id":"","url":"https://api.github.com/users/dylanz","html_url":"https://github.com/dylanz","followers_url":"https://api.github.com/users/dylanz/followers","following_url":"https://api.github.com/users/dylanz/following{/other_user}","gists_url":"https://api.github.com/users/dylanz/gists{/gist_id}","starred_url":"https://api.github.com/users/dylanz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dylanz/subscriptions","organizations_url":"https://api.github.com/users/dylanz/orgs","repos_url":"https://api.github.com/users/dylanz/repos","events_url":"https://api.github.com/users/dylanz/events{/privacy}","received_events_url":"https://api.github.com/users/dylanz/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2015-03-15T08:08:37Z","updated_at":"2015-03-15T08:34:35Z","closed_at":null,"body":"Our cluster was running fine for a couple days, but we started having intermittent downtime.  Most often deisctl list would show active running units, but I was able to catch list output where both the Gateway and Builder were in \"activating\" - \"start-post\" states.  Here is some debug output.  Any insight on why these restarts might be happening would be appreciated!\r\n\r\n```\r\n$ deisctl status deis-store-gateway@1.service\r\n● deis-store-gateway@1.service - deis-store-gateway\r\n   Loaded: loaded (/run/fleet/units/deis-store-gateway@1.service; linked-runtime; vendor preset: disabled)\r\n   Active: active (running) since Sun 2015-03-15 03:00:45 UTC; 4h 51min ago\r\n Main PID: 10912 (sh)\r\n   CGroup: /system.slice/system-deis\\x2dstore\\x2dgateway.slice/deis-store-gateway@1.service\r\n           ├─10912 /bin/sh -c IMAGE=`/run/deis/bin/get_image /deis/store-gateway` && docker run --name deis-store-gateway -h deis-store-gateway --rm -e HOST=$COREOS_PRIVATE_IPV4 -e EXTERNAL_PORT=8888 -p 8888:8888 $IMAGE\r\n           └─10944 docker run --name deis-store-gateway -h deis-store-gateway --rm -e HOST=10.21.2.132 -e EXTERNAL_PORT=8888 -p 8888:8888 deis/store-gateway:v1.4.1\r\n\r\nMar 15 05:17:02 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18365862]\r\nMar 15 05:19:05 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18368923]\r\nMar 15 06:02:16 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18439831]\r\nMar 15 06:03:54 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18442496]\r\nMar 15 07:00:16 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18535170]\r\nMar 15 07:02:00 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18537892]\r\nMar 15 07:03:17 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18539957]\r\nMar 15 07:03:48 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18540791]\r\nMar 15 07:18:52 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18565577]\r\nMar 15 07:31:48 ip-10-21-2-132.us-west-2.compute.internal sh[10912]: Error:  100: Key not found (/deis/store/gateway/masterLock) [18586589]\r\n\r\n\r\n$ deisctl status deis-builder.service\r\n● deis-builder.service - deis-builder\r\n   Loaded: loaded (/run/fleet/units/deis-builder.service; linked-runtime; vendor preset: disabled)\r\n   Active: active (running) since Sun 2015-03-15 03:03:03 UTC; 4h 49min ago\r\n Main PID: 12117 (sh)\r\n   CGroup: /system.slice/deis-builder.service\r\n           ├─12117 /bin/sh -c IMAGE=`/run/deis/bin/get_image /deis/builder` && docker run --name deis-builder --rm -p 2223:22 --volumes-from=deis-builder-data -c 800 -e EXTERNAL_PORT=2223 -e HOST=$COREOS_PRIVATE_IPV4 --privileged -v /etc/environment_proxy:/etc/environment_proxy $IMAGE\r\n           └─12132 docker run --name deis-builder --rm -p 2223:22 --volumes-from=deis-builder-data -c 800 -e EXTERNAL_PORT=2223 -e HOST=10.21.2.132 --privileged -v /etc/environment_proxy:/etc/environment_proxy deis/builder:v1.4.1\r\n\r\nMar 15 03:02:34 ip-10-21-2-132.us-west-2.compute.internal docker[12834]: 6e598451d08d: Pushing\r\nMar 15 03:02:57 ip-10-21-2-132.us-west-2.compute.internal docker[12834]: 6e598451d08d: Buffering to disk\r\nMar 15 03:02:58 ip-10-21-2-132.us-west-2.compute.internal docker[12834]: 6e598451d08d: Image successfully pushed\r\nMar 15 03:02:59 ip-10-21-2-132.us-west-2.compute.internal docker[12834]: 22a00445dca9: Pushing\r\nMar 15 03:03:03 ip-10-21-2-132.us-west-2.compute.internal docker[12834]: 22a00445dca9: Buffering to disk\r\nMar 15 03:03:03 ip-10-21-2-132.us-west-2.compute.internal docker[12834]: 22a00445dca9: Image successfully pushed\r\nMar 15 03:03:03 ip-10-21-2-132.us-west-2.compute.internal docker[12834]: Pushing tag for rev [22a00445dca9] on {http://10.21.2.131:5000/v1/repositories/deis/slugrunner/tags/latest}\r\nMar 15 03:03:03 ip-10-21-2-132.us-west-2.compute.internal sh[12117]: time=\"2015-03-15T03:03:03Z\" level=\"info\" msg=\"-job push(10.21.2.131:5000/deis/slugrunner) = OK (0)\"\r\nMar 15 03:03:03 ip-10-21-2-132.us-west-2.compute.internal systemd[1]: Started deis-builder.\r\nMar 15 06:01:38 ip-10-21-2-132.us-west-2.compute.internal sh[12117]: Error:  501: All the given peers are not reachable (Tried to connect to each peer twice and failed) [0]\r\n\r\n\r\n$ deisctl journal database\r\n=begin\r\nMar 15 07:52:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: wal_e.worker.upload INFO     MSG: completed archiving to a file\r\nMar 15 07:52:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: DETAIL: Archiving to \"s3://db_wal/wal_005/000000030000000D0000001A.lzo\" complete at 2887.17KiB/s.\r\nMar 15 07:52:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: STRUCTURED: time=2015-03-15T07:52:15.682569-00 pid=23896 action=push-wal key=s3://db_wal/wal_005/000000030000000D0000001A.lzo prefix= rate=2887.17 seg=000000030000000D0000001A state=complete\r\nMar 15 07:57:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: wal_e.main   INFO     MSG: starting WAL-E\r\nMar 15 07:57:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: DETAIL: The subcommand is \"wal-push\".\r\nMar 15 07:57:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: STRUCTURED: time=2015-03-15T07:57:15.503544-00 pid=24614\r\nMar 15 07:57:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: wal_e.worker.upload INFO     MSG: begin archiving a file\r\nMar 15 07:57:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: DETAIL: Uploading \"pg_xlog/000000030000000D0000001B\" to \"s3://db_wal/wal_005/000000030000000D0000001B.lzo\".\r\nMar 15 07:57:15 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: STRUCTURED: time=2015-03-15T07:57:15.532104-00 pid=24614 action=push-wal key=s3://db_wal/wal_005/000000030000000D0000001B.lzo prefix= seg=000000030000000D0000001B state=begin\r\nMar 15 07:57:16 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: wal_e.worker.upload INFO     MSG: completed archiving to a file\r\nMar 15 07:57:16 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: DETAIL: Archiving to \"s3://db_wal/wal_005/000000030000000D0000001B.lzo\" complete at 5306.13KiB/s.\r\nMar 15 07:57:16 ip-10-21-2-131.us-west-2.compute.internal sh[1533]: STRUCTURED: time=2015-03-15T07:57:16.147984-00 pid=24614 action=push-wal key=s3://db_wal/wal_005/000000030000000D0000001B.lzo prefix= rate=5306.13 seg=000000030000000D0000001B state=complete\r\n\r\n\r\n$ etcdctl ls --recursive /deis\r\n/deis/controller\r\n/deis/controller/webEnabled\r\n/deis/controller/host\r\n/deis/controller/port\r\n/deis/controller/builderKey\r\n/deis/controller/protocol\r\n/deis/controller/registrationEnabled\r\n/deis/controller/secretKey\r\n/deis/controller/unitHostname\r\n/deis/database\r\n/deis/database/bucketName\r\n/deis/database/engine\r\n/deis/database/name\r\n/deis/database/password\r\n/deis/database/adminPass\r\n/deis/database/adminUser\r\n/deis/database/port\r\n/deis/database/user\r\n/deis/database/host\r\n/deis/router\r\n/deis/router/image\r\n/deis/router/sslCert\r\n/deis/router/sslKey\r\n/deis/router/enforceHTTPS\r\n/deis/router/gzip\r\n/deis/router/hosts\r\n/deis/router/hosts/10.21.2.131\r\n/deis/router/hosts/10.21.2.132\r\n/deis/router/hosts/10.21.1.34\r\n/deis/services\r\n/deis/services/followup\r\n/deis/services/followup/followup_v99.web.2\r\n/deis/services/followup/followup_v99.web.1\r\n/deis/services/followup/followup_v99.web.14\r\n/deis/services/followup/followup_v99.web.10\r\n/deis/services/followup/followup_v99.web.13\r\n/deis/services/followup/followup_v99.webhook_processor.1\r\n/deis/services/followup/followup_v99.web.4\r\n/deis/services/followup/followup_v99.web.6\r\n/deis/services/followup/followup_v99.web.9\r\n/deis/services/followup/followup_v99.web.11\r\n/deis/services/followup/followup_v99.web.5\r\n/deis/services/followup/followup_v99.web.12\r\n/deis/services/followup/followup_v99.web.15\r\n/deis/services/followup/followup_v99.web.8\r\n/deis/services/followup/followup_v99.web.3\r\n/deis/services/followup/followup_v99.web.7\r\n/deis/services/velcro-villager\r\n/deis/cache\r\n/deis/cache/host\r\n/deis/cache/port\r\n/deis/domains\r\n/deis/domains/followup\r\n/deis/logs\r\n/deis/logs/port\r\n/deis/logs/host\r\n/deis/platform\r\n/deis/platform/version\r\n/deis/platform/domain\r\n/deis/platform/sshPrivateKey\r\n/deis/registry\r\n/deis/registry/masterLock\r\n/deis/registry/host\r\n/deis/registry/port\r\n/deis/registry/bucketName\r\n/deis/registry/hosts\r\n/deis/registry/hosts/10.21.1.34\r\n/deis/registry/hosts/10.21.2.131\r\n/deis/registry/hosts/10.21.2.131/host\r\n/deis/registry/hosts/10.21.2.131/port\r\n/deis/registry/hosts/10.21.2.132\r\n/deis/registry/protocol\r\n/deis/registry/secretKey\r\n/deis/store\r\n/deis/store/filesystemSetupComplete\r\n/deis/store/minSize\r\n/deis/store/osds\r\n/deis/store/osds/10.21.1.34\r\n/deis/store/osds/10.21.2.131\r\n/deis/store/osds/10.21.2.132\r\n/deis/store/adminKeyring\r\n/deis/store/delayStart\r\n/deis/store/gateway\r\n/deis/store/gateway/accessKey\r\n/deis/store/gateway/secretKey\r\n/deis/store/gateway/hosts\r\n/deis/store/gateway/hosts/10.21.1.34\r\n/deis/store/gateway/hosts/10.21.2.131\r\n/deis/store/gateway/hosts/10.21.2.132\r\n/deis/store/gateway/hosts/10.21.2.132/host\r\n/deis/store/gateway/hosts/10.21.2.132/port\r\n/deis/store/gateway/masterLock\r\n/deis/store/gateway/host\r\n/deis/store/gateway/port\r\n/deis/store/monKeyring\r\n/deis/store/size\r\n/deis/store/defaultPoolsConfigured\r\n/deis/store/gatewayKeyring\r\n/deis/store/hosts\r\n/deis/store/hosts/10.21.1.34\r\n/deis/store/hosts/10.21.2.131\r\n/deis/store/hosts/10.21.2.132\r\n/deis/store/monSetupComplete\r\n/deis/store/filesystemSetupLock\r\n/deis/store/fsid\r\n/deis/store/monSetupLock\r\n/deis/store/pgNum\r\n/deis/builder\r\n/deis/builder/host\r\n/deis/builder/image\r\n/deis/builder/port\r\n/deis/builder/users\r\n/deis/builder/users/me\r\n/deis/builder/users/me/xx:xx:xx:xx:xx\r\n```"},"comment":{"url":"https://api.github.com/repos/deis/deis/issues/comments/80918981","html_url":"https://github.com/deis/deis/issues/3303#issuecomment-80918981","issue_url":"https://api.github.com/repos/deis/deis/issues/3303","id":80918981,"user":{"login":"ianblenke","id":1844764,"avatar_url":"https://avatars.githubusercontent.com/u/1844764?v=3","gravatar_id":"","url":"https://api.github.com/users/ianblenke","html_url":"https://github.com/ianblenke","followers_url":"https://api.github.com/users/ianblenke/followers","following_url":"https://api.github.com/users/ianblenke/following{/other_user}","gists_url":"https://api.github.com/users/ianblenke/gists{/gist_id}","starred_url":"https://api.github.com/users/ianblenke/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ianblenke/subscriptions","organizations_url":"https://api.github.com/users/ianblenke/orgs","repos_url":"https://api.github.com/users/ianblenke/repos","events_url":"https://api.github.com/users/ianblenke/events{/privacy}","received_events_url":"https://api.github.com/users/ianblenke/received_events","type":"User","site_admin":false},"created_at":"2015-03-15T08:34:35Z","updated_at":"2015-03-15T08:34:35Z","body":"The error I see is:\r\n\r\n    Mar 15 06:01:38 ip-10-21-2-132.us-west-2.compute.internal sh[12117]:\r\n    Error:  501: All the given peers are not reachable (Tried to connect to each peer twice and failed) [0]\r\n\r\nThat suggests etcd encountered a reachability issue, however briefly. Try looking at the etcd logs with `journalctl -u etcd` on each CoreOS machine and see if you can see anything.\r\n\r\nAnother good place to watch for quorum: `docker exec -ti deis-store-monitor ceph -w`\r\n\r\nOperationally, when we had outages with deis-store-gateway, there was some kind of network or instance event that caused ceph to go into an impaired state. \r\n\r\nAlso, operationally, when we had outages with deis-buider, it was because someone did a git push and that push drove the CoreOS machine deis-builder is on deep into swap, often OOMing deis-builder. Other times, it was related to VM clock drift breaking ceph-mon.\r\n\r\n"}}