{"action":"closed","issue":{"url":"https://api.github.com/repos/deis/deis/issues/3238","labels_url":"https://api.github.com/repos/deis/deis/issues/3238/labels{/name}","comments_url":"https://api.github.com/repos/deis/deis/issues/3238/comments","events_url":"https://api.github.com/repos/deis/deis/issues/3238/events","html_url":"https://github.com/deis/deis/issues/3238","id":60326470,"number":3238,"title":"Builder: waiting for confd","user":{"login":"Natsuke","id":5891633,"avatar_url":"https://avatars.githubusercontent.com/u/5891633?v=3","gravatar_id":"","url":"https://api.github.com/users/Natsuke","html_url":"https://github.com/Natsuke","followers_url":"https://api.github.com/users/Natsuke/followers","following_url":"https://api.github.com/users/Natsuke/following{/other_user}","gists_url":"https://api.github.com/users/Natsuke/gists{/gist_id}","starred_url":"https://api.github.com/users/Natsuke/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Natsuke/subscriptions","organizations_url":"https://api.github.com/users/Natsuke/orgs","repos_url":"https://api.github.com/users/Natsuke/repos","events_url":"https://api.github.com/users/Natsuke/events{/privacy}","received_events_url":"https://api.github.com/users/Natsuke/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":5,"created_at":"2015-03-09T10:52:30Z","updated_at":"2015-03-11T07:58:21Z","closed_at":"2015-03-11T07:58:21Z","body":"Hi everyone,\r\n\r\nWe are testing on our server which runs Proxmox.\r\nInstalling deis 1.3.1 works fine and apps pushing works well. Recently updated deis to 1.4.1, same problems appeared.\r\n\r\nAfter a few time some logs on the builder\r\n```\r\nbuilder: waiting for confd to write initial templates...\r\nconfd[3057]: ERROR Config check failed: exit status 1\r\n```\r\n\r\nAnd after testing some system failure, builder eventually fail to start, entering in a confd loop\r\n```\r\n[ ... ]\r\nMar 07 16:03:46 core02 sh[32330]: 2015-03-07T16:03:46Z 9f83e74fd28b confd[748]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:46 core02 sh[32330]: 2015-03-07T16:03:46Z 9f83e74fd28b confd[748]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:46 core02 sh[32330]: builder: waiting for confd to write initial templates...\r\nMar 07 16:03:51 core02 sh[32330]: 2015-03-07T16:03:51Z 9f83e74fd28b confd[769]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:51 core02 sh[32330]: 2015-03-07T16:03:51Z 9f83e74fd28b confd[769]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:51 core02 sh[32330]: builder: waiting for confd to write initial templates...\r\nMar 07 16:03:56 core02 sh[32330]: 2015-03-07T16:03:56Z 9f83e74fd28b confd[789]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:56 core02 sh[32330]: 2015-03-07T16:03:56Z 9f83e74fd28b confd[789]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:56 core02 sh[32330]: 2015-03-07T16:03:56Z 9f83e74fd28b confd[789]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:56 core02 sh[32330]: 2015-03-07T16:03:56Z 9f83e74fd28b confd[789]: ERROR Config check failed: exit status 1\r\nMar 07 16:03:56 core02 sh[32330]: builder: waiting for confd to write initial templates...\r\n[ ... ]\r\nMar 07 16:12:04 core02 systemd[1]: deis-builder.service stop-sigterm timed out. Killing.\r\nMar 07 16:12:04 core02 systemd[1]: deis-builder.service: control process exited, code=killed status=9\r\nMar 07 16:12:04 core02 systemd[1]: Stopped deis-builder.service.\r\nMar 07 16:12:04 core02 systemd[1]: Unit deis-builder.service entered failed state.\r\nMar 07 16:12:04 core02 systemd[1]: deis-builder.service failed.\r\n[ ... ]\r\n```\r\nOther deis services are still running\r\n```\r\n$ fleetctl list-units\r\nUNIT MACHINE ACTIVE SUB\r\ndeis-builder.service 59d987a9.../10.10.8.12 activating start-post\r\ndeis-cache.service 59d987a9.../10.10.8.12 active running\r\ndeis-controller.service 59d987a9.../10.10.8.12 active running\r\ndeis-database.service 59d987a9.../10.10.8.12 active running\r\ndeis-logger.service 59d987a9.../10.10.8.12 active running\r\ndeis-logspout.service 59d987a9.../10.10.8.12 active running\r\ndeis-logspout.service 5b48e78a.../10.10.8.11 active running\r\ndeis-logspout.service 6fa18095.../10.10.8.10 active running\r\ndeis-publisher.service 59d987a9.../10.10.8.12 active running\r\ndeis-publisher.service 5b48e78a.../10.10.8.11 active running\r\ndeis-publisher.service 6fa18095.../10.10.8.10 active running\r\ndeis-registry@1.service 6fa18095.../10.10.8.10 active running\r\ndeis-router@1.service 5b48e78a.../10.10.8.11 active running\r\ndeis-router@2.service 59d987a9.../10.10.8.12 active running\r\ndeis-router@3.service 6fa18095.../10.10.8.10 active running\r\ndeis-store-daemon.service 59d987a9.../10.10.8.12 active running\r\ndeis-store-daemon.service 5b48e78a.../10.10.8.11 active running\r\ndeis-store-daemon.service 6fa18095.../10.10.8.10 active running\r\ndeis-store-gateway@1.service 6fa18095.../10.10.8.10 active running\r\ndeis-store-metadata.service 59d987a9.../10.10.8.12 active running\r\ndeis-store-metadata.service 5b48e78a.../10.10.8.11 active running\r\ndeis-store-metadata.service 6fa18095.../10.10.8.10 active running\r\ndeis-store-monitor.service 59d987a9.../10.10.8.12 active running\r\ndeis-store-monitor.service 5b48e78a.../10.10.8.11 active running\r\ndeis-store-monitor.service 6fa18095.../10.10.8.10 active running\r\ndeis-store-volume.service 59d987a9.../10.10.8.12 active running\r\ndeis-store-volume.service 5b48e78a.../10.10.8.11 active running\r\ndeis-store-volume.service 6fa18095.../10.10.8.10 active running \r\n```\r\nBut after a totally random time, builder sometimes start.\r\n```\r\n[...]\r\nMar 09 10:03:08 core03 sh[14958]: /bin/sh: line 0: echo: write error: Broken pipe\r\nMar 09 10:03:13 core03 sh[14957]: 2015-03-09T10:03:13Z c7209c7b14be confd[1370]: ERROR Config check failed: exit status 1\r\nMar 09 10:03:13 core03 sh[14957]: 2015-03-09T10:03:13Z c7209c7b14be confd[1370]: ERROR Config check failed: exit status 1\r\nMar 09 10:03:13 core03 sh[14957]: builder: waiting for confd to write initial templates...\r\nMar 09 10:03:18 core03 sh[14957]: 2015-03-09T10:03:18Z c7209c7b14be confd[1391]: ERROR Config check failed: exit status 1\r\nMar 09 10:03:18 core03 sh[14957]: 2015-03-09T10:03:18Z c7209c7b14be confd[1391]: ERROR Config check failed: exit status 1\r\nMar 09 10:03:18 core03 sh[14957]: builder: waiting for confd to write initial templates...\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"+job serveapi(unix:///var/run/docker.sock)\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"Listening for HTTP on unix (/var/run/docker.sock)\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"+job init_networkdriver()\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"-job init_networkdriver() = OK (0)\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"Loading containers: start.\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"Loading containers: done.\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"docker daemon: 1.4.1 5bc2ff8; execdriver: native-0.2; graphdriver: btrfs\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"+job acceptconnections()\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"-job acceptconnections() = OK (0)\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"GET /v1.16/images/progrium/cedarish/history\"\r\nMar 09 10:03:24 core03 sh[14957]: time=\"2015-03-09T10:03:24Z\" level=\"info\" msg=\"+job history(progrium/cedarish)\"\r\n[...]\r\n```\r\n\r\nAlso fleet seams unable to receive repsonse from etcd\r\n```\r\n[...]\r\nMar 09 10:25:25 core03 fleetd[648]: INFO client.go:291: Failed getting response from http://localhost:4001/: cancelled\r\nMar 09 10:25:25 core03 fleetd[648]: INFO client.go:291: Failed getting response from http://localhost:4001/: cancelled\r\nMar 09 10:25:25 core03 fleetd[648]: INFO client.go:291: Failed getting response from http://localhost:4001/: cancelled\r\nMar 09 10:25:25 core03 fleetd[648]: INFO client.go:291: Failed getting response from http://localhost:4001/: cancelled\r\n```\r\nBut etcd logs look fine\r\n```\r\n-- Logs begin at Wed 2015-03-04 09:20:48 UTC, end at Mon 2015-03-09 10:46:58 UTC. --\r\nMar 09 09:05:48 core03 systemd[1]: Starting etcd...\r\nMar 09 09:05:48 core03 systemd[1]: Started etcd.\r\nMar 09 09:05:48 core03 systemd[1]: Started etcd.\r\nMar 09 09:05:49 core03 etcd[640]: [etcd] Mar  9 09:05:49.160 INFO      | node003: peer added: 'node001'\r\nMar 09 09:05:49 core03 etcd[640]: [etcd] Mar  9 09:05:49.246 INFO      | node003: peer added: 'node002'\r\nMar 09 09:05:50 core03 etcd[640]: [etcd] Mar  9 09:05:50.238 INFO      | The path /var/lib/etcd/log is in btrfs\r\nMar 09 09:05:50 core03 etcd[640]: [etcd] Mar  9 09:05:50.239 WARNING   | Failed setting NOCOW: skip nonempty file\r\nMar 09 09:05:50 core03 etcd[640]: [etcd] Mar  9 09:05:50.240 INFO      | Peer URLs in log:  / node003 (http://10.10.8.10:7001,http://10.10.8.11:7001,http://10.10.8.12:7001)\r\nMar 09 09:05:50 core03 etcd[640]: [etcd] Mar  9 09:05:50.240 INFO      | Discovery via https://discovery.etcd.io using prefix /1c9316e34a.....\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.467 INFO      | Discovery found peers [http://127.0.0.1:7001 http://127.0.0.1:7001 http://10.10.8.10:7001 http://10.10.8.1\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.467 INFO      | Discovery fetched back peer list: [127.0.0.1:7001 127.0.0.1:7001 10.10.8.10:7001 10.10.8.11:7001]\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.576 INFO      | Send Join Request to http://10.10.8.10:7001/join\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.786 INFO      | node003 joined the cluster via peer 10.10.8.10:7001\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.791 INFO      | etcd server [name node003, listen on :4001, advertised url http://10.10.8.12:4001]\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.791 INFO      | peer server [name node003, listen on :7001, advertised url http://10.10.8.12:7001]\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.791 INFO      | node003 starting in peer mode\r\nMar 09 09:05:51 core03 etcd[640]: [etcd] Mar  9 09:05:51.791 INFO      | node003: state changed from 'initialized' to 'follower'.\r\nMar 09 09:05:55 core03 etcd[640]: [etcd] Mar  9 09:05:55.407 INFO      | node003: snapshot of 4743015 events at index 4743015 completed\r\nMar 09 09:19:10 core03 etcd[640]: [etcd] Mar  9 09:19:10.020 INFO      | node003: snapshot of 10023 events at index 4753038 completed\r\n[...]\r\n```\r\nTell me if I can provide you with more informations. Thanks in advance for your help."}}