Docker compose fails to start
Closed this issue · 4 comments
stelioschar commented
When running the docker-compose docker-compose up I get this error.
etcd-config_1 | OK
go-oauth2-server | INFO: 2016/12/10 12:34:55 factory.go:155 ETCD Endpoints: http://etcd:2379
go-oauth2-server | FATAL: 2016/12/10 12:34:55 factory.go:92 100: Key not found (/config) [3]
etcd_1 | 2016-12-10 11:18:52.097867 W | flags: unrecognized environment variable ETCDCTL_API=3
etcd_1 | 2016-12-10 11:18:52.097963 I | etcdmain: etcd Version: 3.0.15
etcd_1 | 2016-12-10 11:18:52.097970 I | etcdmain: Git SHA: fc00305
etcd_1 | 2016-12-10 11:18:52.097975 I | etcdmain: Go Version: go1.6.3
etcd_1 | 2016-12-10 11:18:52.097981 I | etcdmain: Go OS/Arch: linux/amd64
etcd_1 | 2016-12-10 11:18:52.097987 I | etcdmain: setting maximum number of CPUs to 4, total number of available CPUs is 4
etcd_1 | 2016-12-10 11:18:52.097993 W | etcdmain: no data-dir provided, using default data-dir ./default.etcd
etcd_1 | 2016-12-10 11:18:52.103629 I | etcdmain: listening for peers on http://localhost:2380
etcd_1 | 2016-12-10 11:18:52.103718 I | etcdmain: listening for client requests on 0.0.0.0:2379
etcd_1 | 2016-12-10 11:18:52.115918 I | etcdserver: name = default
etcd_1 | 2016-12-10 11:18:52.115948 I | etcdserver: data dir = default.etcd
etcd_1 | 2016-12-10 11:18:52.115956 I | etcdserver: member dir = default.etcd/member
etcd_1 | 2016-12-10 11:18:52.115962 I | etcdserver: heartbeat = 100ms
etcd_1 | 2016-12-10 11:18:52.115967 I | etcdserver: election = 1000ms
gooauth2server_etcd-config_1 exited with code 0
etcd_1 | 2016-12-10 11:18:52.116103 I | etcdserver: snapshot count = 10000
etcd_1 | 2016-12-10 11:18:52.116131 I | etcdserver: advertise client URLs = http://127.0.0.1:2379
etcd_1 | 2016-12-10 11:18:52.116139 I | etcdserver: initial advertise peer URLs = http://localhost:2380
etcd_1 | 2016-12-10 11:18:52.116207 I | etcdserver: initial cluster = default=http://localhost:2380
etcd_1 | 2016-12-10 11:18:52.165290 I | etcdserver: starting member 8e9e05c52164694d in cluster cdf818194e3a8c32
etcd_1 | 2016-12-10 11:18:52.165370 I | raft: 8e9e05c52164694d became follower at term 0
etcd_1 | 2016-12-10 11:18:52.165390 I | raft: newRaft 8e9e05c52164694d [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
etcd_1 | 2016-12-10 11:18:52.165400 I | raft: 8e9e05c52164694d became follower at term 1
etcd_1 | 2016-12-10 11:18:52.224602 I | etcdserver: starting server... [version: 3.0.15, cluster version: to_be_decided]
etcd_1 | 2016-12-10 11:18:52.225592 I | membership: added member 8e9e05c52164694d [http://localhost:2380] to cluster cdf818194e3a8c32
etcd_1 | 2016-12-10 11:18:52.417490 I | raft: 8e9e05c52164694d is starting a new election at term 1
etcd_1 | 2016-12-10 11:18:52.417595 I | raft: 8e9e05c52164694d became candidate at term 2
etcd_1 | 2016-12-10 11:18:52.417631 I | raft: 8e9e05c52164694d received vote from 8e9e05c52164694d at term 2
etcd_1 | 2016-12-10 11:18:52.417808 I | raft: 8e9e05c52164694d became leader at term 2
etcd_1 | 2016-12-10 11:18:52.417867 I | raft: raft.node: 8e9e05c52164694d elected leader 8e9e05c52164694d at term 2
etcd_1 | 2016-12-10 11:18:52.418712 I | etcdserver: setting up the initial cluster version to 3.0
etcd_1 | 2016-12-10 11:18:52.419736 N | membership: set the initial cluster version to 3.0
etcd_1 | 2016-12-10 11:18:52.419845 I | api: enabled capabilities for version 3.0
etcd_1 | 2016-12-10 11:18:52.419981 I | etcdserver: published {Name:default ClientURLs:[http://127.0.0.1:2379]} to cluster cdf818194e3a8c32
etcd_1 | 2016-12-10 11:18:52.420041 I | etcdmain: ready to serve client requests
etcd_1 | 2016-12-10 11:18:52.420765 N | etcdmain: serving insecure client requests on 0.0.0.0:2379, this is strongly discouraged!
postgres_1 | LOG: database system was shut down at 2016-10-29 15:24:04 UTC
postgres_1 | LOG: MultiXact member wraparound protections are now enabled
postgres_1 | LOG: database system is ready to accept connections
postgres_1 | LOG: autovacuum launcher started
go-oauth2-server exited with code 1RichardKnop commented
The problem seems to be the go-oauth2-server container starts too soon - before postgres container has been properly created. So it fails to connect to postgres and run database migrations.
Not sure what is causing this. Try running docker-compose up again. It usually fixes itself 2nd or 3rd time you run it.
RichardKnop commented
This line should cause the api container to start after postgres is already running. Doesn't seem to work reliably.
https://github.com/RichardKnop/go-oauth2-server/blob/master/docker-compose.yml#L32
stelioschar commented
I tried to run docker-compose up again and again with no result.
I'm attaching you the logs from the exited containers
▶ docker-compose ps
Name Command State Ports
---------------------------------------------------------------------------------
go-oauth2-server /docker-entrypoint.sh go-o ... Exit 1
gooauth2server_etcd-config_1 /docker-etcd-config-entryp ... Exit 2
gooauth2server_etcd_1 etcd --initial-cluster-sta ... Exit 2
gooauth2server_postgres_1 /docker-entrypoint.sh postgres Up 5432/tcp
▶ docker logs go-oauth2-server
INFO: 2016/12/11 08:03:04 factory.go:169 ETCD Endpoints: http://etcd:2379
FATAL: 2016/12/11 08:03:09 factory.go:84 grpc: timed out when dialing
INFO: 2016/12/11 08:23:20 factory.go:169 ETCD Endpoints: http://etcd:2379
FATAL: 2016/12/11 08:23:25 factory.go:84 grpc: timed out when dialing
▶ docker logs gooauth2server_etcd-config_1
2016/12/11 08:23:22 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp: lookup etcd on 127.0.0.11:53: server misbehaving"; Reconnecting to {"etcd:2379" <nil>}
2016/12/11 08:23:23 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp: lookup etcd on 127.0.0.11:53: server misbehaving"; Reconnecting to {"etcd:2379" <nil>}
Error: grpc: timed out when dialing
▶ docker logs gooauth2server_etcd_1
2016-12-11 08:23:20.332055 W | flags: unrecognized environment variable ETCDCTL_API=3
2016-12-11 08:23:20.332629 I | etcdmain: etcd Version: 3.0.15
2016-12-11 08:23:20.332649 I | etcdmain: Git SHA: fc00305
2016-12-11 08:23:20.332659 I | etcdmain: Go Version: go1.6.3
2016-12-11 08:23:20.332667 I | etcdmain: Go OS/Arch: linux/amd64
2016-12-11 08:23:20.332676 I | etcdmain: setting maximum number of CPUs to 1, total number of available CPUs is 1
2016-12-11 08:23:20.332685 W | etcdmain: no data-dir provided, using default data-dir ./default.etcd
2016-12-11 08:23:20.334178 N | etcdmain: the server is already initialized as member before, starting as etcd member...
2016-12-11 08:23:20.338958 I | etcdmain: listening for peers on http://localhost:2380
2016-12-11 08:23:20.339024 I | etcdmain: listening for client requests on 0.0.0.0:2379
2016-12-11 08:23:20.349477 C | backend: cannot open database at default.etcd/member/snap/db (invalid argument)
panic: cannot open database at default.etcd/member/snap/db (invalid argument)
goroutine 1 [running]:
panic(0xd450a0, 0xc82019f4c0)
/usr/local/go/src/runtime/panic.go:481 +0x3e6
github.com/coreos/etcd/cmd/vendor/github.com/coreos/pkg/capnslog.(*PackageLogger).Panicf(0xc82016e080, 0x11dfe60, 0x1f, 0xc8200ff8f0, 0x2, 0x2)
/home/gyuho/go/src/github.com/coreos/etcd/cmd/vendor/github.com/coreos/pkg/capnslog/pkg_logger.go:75 +0x191
github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/mvcc/backend.newBackend(0xc8201b81e0, 0x1b, 0x5f5e100, 0x2710, 0x0)
/home/gyuho/go/src/github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/mvcc/backend/backend.go:106 +0x1ee
github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/mvcc/backend.NewDefaultBackend(0xc8201b81e0, 0x1b, 0x0, 0x0)
/home/gyuho/go/src/github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/mvcc/backend/backend.go:100 +0x53
github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdserver.NewServer(0xc82006be40, 0x0, 0x0, 0x0)
/home/gyuho/go/src/github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdserver/server.go:248 +0x69c
github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdmain.startEtcd(0xc820023c00, 0x0, 0x0, 0x0)
/home/gyuho/go/src/github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdmain/etcd.go:374 +0x245f
github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdmain.startEtcdOrProxyV2()
/home/gyuho/go/src/github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdmain/etcd.go:116 +0x2101
github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdmain.Main()
/home/gyuho/go/src/github.com/coreos/etcd/cmd/vendor/github.com/coreos/etcd/etcdmain/main.go:36 +0x21e
main.main()
/home/gyuho/go/src/github.com/coreos/etcd/cmd/main.go:28 +0x14
RichardKnop commented
@stelioschar I have refactored docker compose so it should be working much better now.