envtool panics on timeout

[AlekSi]

What should be done?

See #2451 (comment)

envtool should not fail like that. It should provide a helpful error message.

Where?

envtool.go

Definition of Done

On that system, the error message should be about timeout, and Docker Compose logs should be provided.

[syasyayas]

I revisioned the problem and it seems that the issue appeared not because of mongo, but rather because of tigris setup, which caused panic here:

FerretDB/cmd/envtool/envtool.go

Line 183 in 1479b0c

defer db.Driver.Close()

Mongo containers do provide their logs once I comment out the tigris setup:

task: [env-logs] docker compose logs --follow
ferretdb_mongodb_secured   | 
ferretdb_mongodb_secured   | WARNING: MongoDB 5.0+ requires a CPU with AVX support, and your current system does not appear to have that!
ferretdb_mongodb_secured   |   see https://jira.mongodb.org/browse/SERVER-54407
ferretdb_mongodb_secured   |   see also https://www.mongodb.com/community/forums/t/mongodb-5-0-cpu-intel-g4650-compatibility/116610/2
ferretdb_mongodb_secured   |   see also https://github.com/docker-library/mongo/issues/485#issuecomment-891991814
ferretdb_mongodb_secured   | 

Tigris itself fails of some illegal instructions I'm not sure about, but I assume it may be because my cpu does not support AVX:

ferretdb_tigris4           | Waiting for foundationdb to start
ferretdb_tigris4           | /server/service.sh: line 37:     8 Illegal instruction     (core dumped) fdbcli --exec 'configure new single memory'
ferretdb_tigris4           | /server/service.sh: line 42:     7 Illegal instruction     (core dumped) fdbserver --listen-address 127.0.0.1:4500 --public-address 127.0.0.1:4500 --datadir /var/lib/foundationdb/data --logdir /var/lib/foundationdb/logs --locality-zoneid tigris --locality-machineid tigris

Full env-up logs with disabled tigris setup:

Full task env-up logs

``` yaroslav@helen-N53Jg:~/go/src/FerretDB$ sudo "PATH=$PATH" bin/task env-up task: [env-up-detach] docker version task: [gen-version] go generate -x ./build/version go run ./generate.go Client: Docker Engine - Community Version: 23.0.4 API version: 1.41 (downgraded from 1.42) Go version: go1.19.8 Git commit: f480fb1 Built: Fri Apr 14 10:32:03 2023 OS/Arch: linux/amd64 Context: default

Server:
Engine:
Version: 20.10.17
API version: 1.41 (minimum version 1.12)
Go version: go1.18.10
Git commit: a89b842
Built: Tue Mar 7 06:30:14 2023
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: v1.6.6
GitCommit: 10c12954828e7c7c9b6e0ea9b0c02b01407d3ae1
runc:
Version: 1.1.2
GitCommit:
docker-init:
Version: 0.19.0
GitCommit: de40ad0
task: [env-up-detach] docker compose version
Docker Compose version v2.17.2
task: [env-up-detach] docker compose up --always-recreate-deps --force-recreate --remove-orphans --renew-anon-volumes -t 0 --detach --build --pull=always postgres postgres_secured tigris tigris1 tigris2 tigris3 tigris4 mongodb mongodb_secured jaeger

package.txt: bin
branch.txt: main
commit.txt: f0958a9
version.txt: v1.0.0-56-gf0958a9-dirty
task: [env-setup] go run -race=true ./cmd/envtool
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.0s (0/0)
[+] Building 0.3s (0/1)
=> [internal] load build definition from tigris.Dockerfile 0.2s
[+] Building 0.2s (0/1)
=> [internal] load build definition from tigris.Dockerfile 0.2s
[+] Building 0.2s (0/1)
=> [internal] load build definition from mongo6.Dockerfile 0.2s
[+] Building 0.3s (1/1)
=> [internal] load build definition from tigris.Dockerfile 0.3s
[+] Building 0.4s (1/1)
[+] Building 0.3s (1/1)
=> [internal] load build definition from mongo6.Dockerfile 0.3s
[+] Building 0.1s (1/1)
[+] Building 0.5s (1/2)
=> [internal] load build definition from tigris.Dockerfile 0.3s
=> => transferring dockerfile: 38B 0.0s
[+] Building 0.4s (1/1)
[+] Building 0.2s (1/1)
=> [internal] load build definition from postgres.Dockerfile 0.2s
[+] Building 0.4s (1/1)
[+] Building 0.5s (2/2)
[+] Building 0.7s (2/2)
=> [internal] load build definition from tigris.Dockerfile 0.3s
[+] Building 0.7s (2/2)
=> [internal] load build definition from tigris.Dockerfile 0.3s
[+] Building 0.7s (2/2)
=> [internal] load build definition from mongo6.Dockerfile 0.3s
[+] Building 0.6s (2/2)
=> [internal] load build definition from jaeger.Dockerfile 0.3s
[+] Building 0.5s (2/2)
=> [internal] load build definition from postgres.Dockerfile 0.2s
[+] Building 0.6s (2/2)
=> [internal] load build definition from mongo6.Dockerfile 0.2s
[+] Building 0.6s (2/2)
=> [internal] load build definition from tigris.Dockerfile 0.2s
[+] Building 0.7s (2/2)
=> [internal] load build definition from jaeger.Dockerfile 0.3s
[+] Building 1.0s (2/3)
[+] Building 1.1s (2/3)
[+] Building 1.0s (2/3)
[+] Building 1.9s (2/3)
=> [internal] load build definition from tigris.Dockerfile 0.2s
[+] Building 2.2s (3/3)
=> [internal] load build definition from mongo6.Dockerfile 0.2s
=> => transferring dockerfile: 61B 0.0s
=> [internal] load .dockerignore 0.0s
=> => transferring context: 2B 0.0s
=> [internal] load metadata for docker.io/library/mongo:6.0.5 1.3s
[+] Building 2.2s (3/4)
[+] Building 2.3s (4/5)
=> [internal] load build definition from jaeger.Dockerfile 0.3s
=> => transferring dockerfile: 81B 0.0s
=> [internal] load .dockerignore 0.0s
[+] Building 2.3s (4/5)
=> [internal] load build definition from tigris.Dockerfile 0.2s
=> => transferring dockerfile: 87B 0.0s
[+] Building 2.6s (5/5) FINISHED
=> [internal] load build definition from tigris.Dockerfile 0.3s
=> => transferring dockerfile: 38B 0.0s
=> [internal] load .dockerignore 0.1s
=> => transferring context: 2B 0.0s
[+] Building 2.4s (4/5)
=> [internal] load build definition from tigris.Dockerfile 0.3s
=> => transferring dockerfile: 87B 0.0s
[+] Building 2.1s (5/5) FINISHED
=> [internal] load build definition from tigris.Dockerfile 0.0s
=> => transferring dockerfile: 38B 0.0s
=> [internal] load .dockerignore 0.0s
[+] Building 2.3s (5/5) FINISHED
[+] Building 2.3s (5/5) FINISHED
[+] Building 2.5s (5/5) FINISHED
=> [internal] load build definition from tigris.Dockerfile 0.3s
=> => transferring dockerfile: 87B 0.0s
=> [internal] load .dockerignore 0.0s
=> => transferring context: 2B 0.0s
[+] Building 2.2s (4/5)
=> [internal] load build definition from tigris.Dockerfile 0.2s
=> => transferring dockerfile: 38B 0.0s
[+] Building 2.3s (4/4)
[+] Building 2.3s (4/5)
=> [internal] load build definition from postgres.Dockerfile 0.2s
[+] Building 2.4s (5/5) FINISHED
=> [internal] load build definition from mongo6.Dockerfile 0.2s
=> => transferring dockerfile: 61B 0.0s
=> [internal] load .dockerignore 0.0s
[+] Building 2.5s (5/5) FINISHED
=> [internal] load build definition from mongo6.Dockerfile 0.3s
[+] Building 2.3s (5/5) FINISHED
=> [internal] load build definition from tigris.Dockerfile 0.2s
[+] Building 2.4s (5/5) FINISHED
=> [internal] load build definition from postgres.Dockerfile 0.2s
[+] Building 2.3s (5/5) FINISHED
=> [internal] load build definition from postgres.Dockerfile 0.1s
=> => transferring dockerfile: 65B 0.0s
=> [internal] load .dockerignore 0.1s
=> => transferring context: 2B 0.0s
=> [internal] load metadata for docker.io/library/postgres:15.2 1.2s
=> CACHED [1/1] FROM docker.io/library/postgres:15.2@sha256:6cc97262444f1c45171081bc5a1d4c28b883ea46a6e0d1a45a8eac4a7f4767ab 0.0s
=> exporting to image 0.2s
=> => exporting layers 0.0s
=> => writing image sha256:5cb435785a5cc5138d9286a45518bc76e3f062cc3cfbcd5429f38267bb3e7889 0.0s
=> => naming to docker.io/library/ferretdb-postgres_secured 0.0s
2023-04-20T21:43:41.075+0300 INFO postgres envtool/envtool.go:60 Waiting for 127.0.0.1:5432 to be up...
2023-04-20T21:43:41.079+0300 INFO debug debug/debug.go:95 Starting debug server on http://127.0.0.1:8089/
[+] Running 0/0
⠋ Container ferretdb_tigris Recreate 0.1s
⠋ Container ferretdb_mongodb Recreate 0.1s
⠋ Container ferretdb_tigris4 Recreate 0.1s
⠋ Container ferretdb_postgres_secured Recreate 0.1s
⠋ Container ferretdb_mongodb_secured Recreate 0.1s
⠋ Container ferretdb_tigris1 Recreate 0.1s
⠋ Container ferretdb_tigris3 Recreate 0.1s
⠋ Container ferretdb_jaeger Recreate 0.1s
⠋ Container ferretdb_postgres Recreate 0.1s
⠋ Container ferretdb_tigris2 Recreate 0.1s
2023-04-20T21:43:41.193+0300 INFO postgres.pgdb tracelog/tracelog.go:335 Connect {"host": "127.0.0.1", "port": 5432, "database": "ferretdb", "time": "107.108904ms", "pid": 84}
[+] Running 0/10:41.202+0300 INFO postgres.pgdb tracelog/tracelog.go:335 Prepare {"name": "stmtcache_1", "sql": "SHOW server_ve ⠙ Container ferretdb_tigris Recreate 0.2s
⠙ Container ferretdb_mongodb Recreate 0.2s ⠙ Container ferretdb_tigris4 Recreate 0.2s
⠙ Container ferretdb_postgres_secured Recreate 0.2s ⠙ Container ferretdb_mongodb_secured Recreate 0.2s
⠙ Container ferretdb_tigris1 Recreate 0.2s ⠙ Container ferretdb_tigris3 Recreate 0.2s
⠙ Container ferretdb_jaeger Recreate 0.2s
⠙ Container ferretdb_postgres Recreate 0.2s ⠙ Container ferretdb_tigris2 Recreate 0.2s
2023-04-20T21:43:41.280+0300 INFO postgres.pgdb tracelog/tracelog.go:335 Query {"sql": "CREATE SCHEMA IF NOT EXISTS "admin"", "args": [], "time": "67.31951ms", "commandTag": "CREATE SCHEMA", "pid": 84}
[+] Running 0/10:41.296+0300 INFO postgres.pgdb tracelog/tracelog.go:335 Query {"time": "15.708227ms", "commandTag": "COMMIT" ⠹ Container ferretdb_tigris Recreate 0.3s
[+] Running 0/10retdb_mongodb Recreate 0.3s ⠼ Container ferretdb_tigris Recreate 0.5s
⠼ Container ferretdb_mongodb Recreate 0.5s ⠼ Container ferretdb_tigris4 Recreate 0.5s
⠼ Container ferretdb_postgres_secured Recreate 0.5s [+] Running 2/10retdb_mongodb_secured Recreate 0.5s
⠴ Container ferretdb_tigris Recreate 0.6s
✔ Container ferretdb_mongodb Recreated 0.6s ⠴ Container ferretdb_tigris4 Recreate 0.6s
⠴ Container ferretdb_postgres_secured Recreate 0.6s ✔ Container ferretdb_mongodb_secured Recreated 0.6s
⠴ Container ferretdb_tigris1 Recreate 0.6s ⠴ Container ferretdb_tigris3 Recreate 0.6s
⠴ Container ferretdb_jaeger Recreate 0.6s ⠴ Container ferretdb_postgres Recreate 0.6s
⠴ Container ferretdb_tigris2 Recreate 0.6s
[+] Running 2/10:41.730+0300 INFO postgres_secured.pgdb tracelog/tracelog.go:335 Connect {"host": "127.0.0.1", "port": 5433, "d ⠦ Container ferretdb_tigris Recreate 0.7s
✔ Container ferretdb_mongodb Recreated 0.6s ⠦ Container ferretdb_tigris4 Recreate 0.7s
⠦ Container ferretdb_postgres_secured Recreate 0.7s ✔ Container ferretdb_mongodb_secured Recreated 0.6s
⠦ Container ferretdb_tigris1 Recreate 0.7s ⠦ Container ferretdb_tigris3 Recreate 0.7s
⠦ Container ferretdb_jaeger Recreate 0.7s ⠦ Container ferretdb_postgres Recreate 0.7s
⠦ Container ferretdb_tigris2 Recreate 0.7s
2023-04-20T21:43:41.738+0300 INFO postgres_secured.pgdb tracelog/tracelog.go:335 Query {"sql": "begin", "args": [], "time": "455.336µs", "commandTag": "BEGIN", "pid": 82}
2023-04-20T21:43:41.742+0300 INFO postgres_secured.pgdb tracelog/tracelog.go:335 Query {"sql": "CREATE SCHEMA IF NOT EXISTS "admin"", "args": [], "time": "3.576168ms", "commandTag": "CREATE SCHEMA", "pid": 82}
2023-04-20T21:43:41.743+0300 INFO postgres_secured.pgdb tracelog/tracelog.go:335 Query {"args": [], "time": "1.206178ms", "commandTag": "COMMIT", "pid": 82, "sql": "commit"}
[+] Running 2/10:41.744+0300 INFO postgres_secured.pgdb tracelog/tracelog.go:335 Query {"sql": "begin", "args": [], "time": " ⠇ Container ferretdb_tigris Recreate 0.9s
✔ Container ferretdb_mongodb Recreated 0.6s ⠇ Container ferretdb_tigris4 Recreate 0.9s
⠇ Container ferretdb_postgres_secured Recreate 0.9s ✔ Container ferretdb_mongodb_secured Recreated 0.6s
⠇ Container ferretdb_tigris1 Recreate 0.9s
[+] Running 2/10retdb_tigris3 Recreate 0.9s [+] Running 2/10retdb_tigris Recreate 1.0s
[+] Running 2/10retdb_tigris Recreate 1.4s [+] Running 7/10retdb_tigris Recreate 1.9s
[+] Running 0/10retdb_tigris Recreate 2.5s [+] Running 0/10retdb_tigris Starting 2.6s
[+] Running 0/10retdb_tigris Starting 3.0s [+] Running 0/10retdb_tigris Starting 3.1s
⠿ Container ferretdb_tigris Starting 3.9s
⠿ Container ferretdb_mongodb Starting 3.9s
[+] Running 10/10etdb_tigris4 Starting 3.9s
✔ Container ferretdb_tigris Started 8.3s
✔ Container ferretdb_mongodb Started 11.3s
✔ Container ferretdb_tigris4 Started 9.5s
✔ Container ferretdb_postgres_secured Started 6.3s
✔ Container ferretdb_mongodb_secured Started 7.2s
✔ Container ferretdb_tigris1 Started 8.2s
✔ Container ferretdb_tigris3 Started 9.5s
✔ Container ferretdb_jaeger Started 7.3s
✔ Container ferretdb_postgres Started 10.4s
✔ Container ferretdb_tigris2 Started 9.6s
task: [env-logs] docker compose ps --all
NAME IMAGE COMMAND SERVICE CREATED STATUS PORTS
ferretdb_jaeger ferretdb-jaeger "/go/bin/all-in-one-…" jaeger 12 seconds ago Up 4 seconds 5775/udp, 5778/tcp, 0.0.0.0:14268->14268/tcp, :::14268->14268/tcp, 6831-6832/udp, 14250/tcp, 0.0.0.0:16686->16686/tcp, :::16686->16686/tcp
ferretdb_mongodb ferretdb-mongodb "docker-entrypoint.s…" mongodb 12 seconds ago Up Less than a second 0.0.0.0:47017->27017/tcp, :::47017->27017/tcp
ferretdb_mongodb_secured ferretdb-mongodb_secured "docker-entrypoint.s…" mongodb_secured 12 seconds ago Up 4 seconds 0.0.0.0:47018->27017/tcp, :::47018->27017/tcp
ferretdb_postgres ferretdb-postgres "docker-entrypoint.s…" postgres 12 seconds ago Up 1 second 0.0.0.0:5432->5432/tcp, :::5432->5432/tcp
ferretdb_postgres_secured ferretdb-postgres_secured "docker-entrypoint.s…" postgres_secured 12 seconds ago Up 5 seconds 0.0.0.0:5433->5432/tcp, :::5433->5432/tcp
ferretdb_tigris ferretdb-tigris "/bin/bash /server/s…" tigris 12 seconds ago Up 3 seconds 0.0.0.0:8081->8081/tcp, :::8081->8081/tcp
ferretdb_tigris1 ferretdb-tigris1 "/bin/bash /server/s…" tigris1 12 seconds ago Up 3 seconds 0.0.0.0:8091->8081/tcp, :::8091->8081/tcp
ferretdb_tigris2 ferretdb-tigris2 "/bin/bash /server/s…" tigris2 12 seconds ago Up 2 seconds 0.0.0.0:8092->8081/tcp, :::8092->8081/tcp
ferretdb_tigris3 ferretdb-tigris3 "/bin/bash /server/s…" tigris3 12 seconds ago Up 2 seconds 0.0.0.0:8093->8081/tcp, :::8093->8081/tcp
ferretdb_tigris4 ferretdb-tigris4 "/bin/bash /server/s…" tigris4 12 seconds ago Up 2 seconds 0.0.0.0:8094->8081/tcp, :::8094->8081/tcp
task: [env-logs] docker compose logs --follow
ferretdb_tigris3 | Waiting for foundationdb to start
ferretdb_tigris3 | /server/service.sh: line 37: 8 Illegal instruction (core dumped) fdbcli --exec 'configure new single memory'
ferretdb_tigris3 | /server/service.sh: line 42: 7 Illegal instruction (core dumped) fdbserver --listen-address 127.0.0.1:4500 --public-address 127.0.0.1:4500 --datadir /var/lib/foundationdb/data --logdir /var/lib/foundationdb/logs --locality-zoneid tigris --locality-machineid tigris
ferretdb_mongodb_secured |
ferretdb_mongodb_secured | WARNING: MongoDB 5.0+ requires a CPU with AVX support, and your current system does not appear to have that!
ferretdb_mongodb_secured | see https://jira.mongodb.org/browse/SERVER-54407
ferretdb_mongodb_secured | see also https://www.mongodb.com/community/forums/t/mongodb-5-0-cpu-intel-g4650-compatibility/116610/2
ferretdb_mongodb_secured | see also docker-library/mongo#485 (comment)
ferretdb_mongodb_secured |
ferretdb_tigris2 | Waiting for foundationdb to start
ferretdb_tigris2 | /server/service.sh: line 37: 8 Illegal instruction (core dumped) fdbcli --exec 'configure new single memory'
ferretdb_tigris2 | /server/service.sh: line 42: 7 Illegal instruction (core dumped) fdbserver --listen-address 127.0.0.1:4500 --public-address 127.0.0.1:4500 --datadir /var/lib/foundationdb/data --logdir /var/lib/foundationdb/logs --locality-zoneid tigris --locality-machineid tigris
ferretdb_postgres_secured | The files belonging to this database system will be owned by user "postgres".
ferretdb_tigris1 | Waiting for foundationdb to start
ferretdb_jaeger | 2023/04/20 18:43:48 maxprocs: Leaving GOMAXPROCS=4: CPU quota undefined
ferretdb_jaeger | {"level":"info","ts":1682016228.5490263,"caller":"flags/service.go:119","msg":"Mounting metrics handler on admin server","route":"/metrics"}
ferretdb_tigris1 | /server/service.sh: line 37: 7 Illegal instruction (core dumped) fdbserver --listen-address 127.0.0.1:4500 --public-address 127.0.0.1:4500 --datadir /var/lib/foundationdb/data --logdir /var/lib/foundationdb/logs --locality-zoneid tigris --locality-machineid tigris
ferretdb_postgres_secured | This user must also own the server process.
ferretdb_tigris1 | /server/service.sh: line 37: 8 Illegal instruction (core dumped) fdbcli --exec 'configure new single memory'
ferretdb_jaeger | {"level":"info","ts":1682016228.552848,"caller":"flags/service.go:125","msg":"Mounting expvar handler on admin server","route":"/debug/vars"}
ferretdb_postgres_secured |
ferretdb_tigris | Waiting for foundationdb to start
ferretdb_postgres_secured | The database cluster will be initialized with locale "en_US.utf8".
ferretdb_postgres_secured | The default database encoding has accordingly been set to "UTF8".
ferretdb_jaeger | {"level":"info","ts":1682016228.5531998,"caller":"flags/admin.go:129","msg":"Mounting health check on admin server","route":"/"}
ferretdb_jaeger | {"level":"info","ts":1682016228.5533247,"caller":"flags/admin.go:143","msg":"Starting admin HTTP server","http-addr":":14269"}
ferretdb_tigris | /server/service.sh: line 37: 7 Illegal instruction (core dumped) fdbserver --listen-address 127.0.0.1:4500 --public-address 127.0.0.1:4500 --datadir /var/lib/foundationdb/data --logdir /var/lib/foundationdb/logs --locality-zoneid tigris --locality-machineid tigris
ferretdb_jaeger | {"level":"info","ts":1682016228.553387,"caller":"flags/admin.go:121","msg":"Admin server started","http.host-port":"[::]:14269","health-status":"unavailable"}
ferretdb_postgres_secured | The default text search configuration will be set to "english".
ferretdb_postgres_secured |
ferretdb_jaeger | {"level":"info","ts":1682016228.5619779,"caller":"memory/factory.go:66","msg":"Memory storage initialized","configuration":{"MaxTraces":0}}
ferretdb_postgres_secured | Data page checksums are disabled.
ferretdb_tigris | /server/service.sh: line 37: 8 Illegal instruction (core dumped) fdbcli --exec 'configure new single memory'
ferretdb_jaeger | {"level":"info","ts":1682016228.56591,"caller":"static/strategy_store.go:138","msg":"Loading sampling strategies","filename":"/etc/jaeger/sampling_strategies.json"}
ferretdb_postgres_secured |
ferretdb_jaeger | {"level":"info","ts":1682016228.6163456,"caller":"grpc@v1.54.0/server.go:632","msg":"[core][Server #1] Server created","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | fixing permissions on existing directory /var/lib/postgresql/data ... ok
ferretdb_jaeger | {"level":"info","ts":1682016228.6232414,"caller":"server/grpc.go:104","msg":"Starting jaeger-collector gRPC server","grpc.host-port":"[::]:14250"}
ferretdb_postgres_secured | creating subdirectories ... ok
ferretdb_jaeger | {"level":"info","ts":1682016228.6240928,"caller":"server/http.go:56","msg":"Starting jaeger-collector HTTP server","http host-port":":14268"}
ferretdb_postgres_secured | selecting dynamic shared memory implementation ... posix
ferretdb_jaeger | {"level":"info","ts":1682016228.6244824,"caller":"server/zipkin.go:53","msg":"Not listening for Zipkin HTTP traffic, port not configured"}
ferretdb_postgres_secured | selecting default max_connections ... 100
ferretdb_jaeger | {"level":"info","ts":1682016228.624535,"caller":"grpc/builder.go:73","msg":"Agent requested insecure grpc connection to collector(s)"}
ferretdb_jaeger | {"level":"info","ts":1682016228.6246488,"caller":"grpc@v1.54.0/clientconn.go:105","msg":"[core][Channel #3] Channel created","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | selecting default shared_buffers ... 128MB
ferretdb_jaeger | {"level":"info","ts":1682016228.6243205,"caller":"grpc@v1.54.0/server.go:820","msg":"[core][Server #1 ListenSocket #2] ListenSocket created","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | selecting default time zone ... America/St_Johns
ferretdb_jaeger | {"level":"info","ts":1682016228.6259217,"caller":"grpc@v1.54.0/clientconn.go:1569","msg":"[core][Channel #3] original dial target is: ":14250"","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | creating configuration files ... ok
ferretdb_jaeger | {"level":"info","ts":1682016228.625958,"caller":"grpc@v1.54.0/clientconn.go:1574","msg":"[core][Channel #3] dial target ":14250" parse failed: parse ":14250": missing protocol scheme","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | running bootstrap script ... ok
ferretdb_jaeger | {"level":"info","ts":1682016228.625983,"caller":"grpc@v1.54.0/clientconn.go:1589","msg":"[core][Channel #3] fallback to scheme "passthrough"","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | performing post-bootstrap initialization ... ok
ferretdb_jaeger | {"level":"info","ts":1682016228.6260402,"caller":"grpc@v1.54.0/clientconn.go:1597","msg":"[core][Channel #3] parsed dial target is: {Scheme:passthrough Authority: URL:{Scheme:passthrough Opaque: User: Host: Path:/:14250 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | initdb: warning: enabling "trust" authentication for local connections
ferretdb_jaeger | {"level":"info","ts":1682016228.626067,"caller":"grpc@v1.54.0/clientconn.go:273","msg":"[core][Channel #3] Channel authority set to "localhost:14250"","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
ferretdb_jaeger | {"level":"info","ts":1682016228.6264303,"caller":"grpc@v1.54.0/resolver_conn_wrapper.go:175","msg":"[core][Channel #3] Resolver state updated: {\n "Addresses": [\n {\n "Addr": ":14250",\n "ServerName": "",\n "Attributes": null,\n "BalancerAttributes": null,\n "Type": 0,\n "Metadata": null\n }\n ],\n "ServiceConfig": null,\n "Attributes": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | syncing data to disk ... ok
ferretdb_jaeger | {"level":"info","ts":1682016228.6265235,"caller":"grpc@v1.54.0/balancer_conn_wrappers.go:274","msg":"[core][Channel #3] Channel switches to new LB policy "round_robin"","system":"grpc","grpc_log":true}
ferretdb_postgres_secured |
ferretdb_mongodb |
ferretdb_postgres_secured |
ferretdb_postgres_secured | Success. You can now start the database server using:
ferretdb_postgres_secured |
ferretdb_mongodb | WARNING: MongoDB 5.0+ requires a CPU with AVX support, and your current system does not appear to have that!
ferretdb_mongodb | see https://jira.mongodb.org/browse/SERVER-54407
ferretdb_mongodb | see also https://www.mongodb.com/community/forums/t/mongodb-5-0-cpu-intel-g4650-compatibility/116610/2
ferretdb_mongodb | see also docker-library/mongo#485 (comment)
ferretdb_jaeger | {"level":"info","ts":1682016228.6274564,"caller":"grpc@v1.54.0/balancer_conn_wrappers.go:306","msg":"[core][Channel #3 SubChannel #4] Subchannel created","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6275375,"caller":"base/balancer.go:177","msg":"[roundrobin]roundrobinPicker: Build called with info: {map[]}","system":"grpc","grpc_log":true}
ferretdb_mongodb |
ferretdb_postgres_secured | pg_ctl -D /var/lib/postgresql/data -l logfile start
ferretdb_jaeger | {"level":"info","ts":1682016228.6275764,"caller":"grpc@v1.54.0/clientconn.go:428","msg":"[core][Channel #3] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
ferretdb_tigris4 | Waiting for foundationdb to start
ferretdb_tigris4 | /server/service.sh: line 37: 8 Illegal instruction (core dumped) fdbcli --exec 'configure new single memory'
ferretdb_tigris4 | /server/service.sh: line 42: 7 Illegal instruction (core dumped) fdbserver --listen-address 127.0.0.1:4500 --public-address 127.0.0.1:4500 --datadir /var/lib/foundationdb/data --logdir /var/lib/foundationdb/logs --locality-zoneid tigris --locality-machineid tigris
ferretdb_postgres_secured |
ferretdb_jaeger | {"level":"info","ts":1682016228.6277275,"caller":"grpc@v1.54.0/clientconn.go:1117","msg":"[core][Channel #3 SubChannel #4] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
ferretdb_postgres_secured | waiting for server to start....2023-04-20 16:13:49.307 NDT [48] LOG: starting PostgreSQL 15.2 (Debian 15.2-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
ferretdb_postgres_secured | 2023-04-20 16:13:49.314 NDT [48] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
ferretdb_postgres_secured | 2023-04-20 16:13:49.340 NDT [51] LOG: database system was shut down at 2023-04-20 16:13:48 NDT
ferretdb_postgres_secured | 2023-04-20 16:13:49.360 NDT [48] LOG: database system is ready to accept connections
ferretdb_postgres_secured | done
ferretdb_postgres_secured | server started
ferretdb_postgres_secured | CREATE DATABASE
ferretdb_postgres_secured |
ferretdb_postgres_secured |
ferretdb_postgres_secured | /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
ferretdb_postgres_secured |
ferretdb_postgres_secured | 2023-04-20 16:13:50.242 NDT [48] LOG: received fast shutdown request
ferretdb_postgres_secured | waiting for server to shut down....2023-04-20 16:13:50.245 NDT [48] LOG: aborting any active transactions
ferretdb_postgres_secured | 2023-04-20 16:13:50.253 NDT [48] LOG: background worker "logical replication launcher" (PID 54) exited with exit code 1
ferretdb_postgres_secured | 2023-04-20 16:13:50.255 NDT [49] LOG: shutting down
ferretdb_postgres_secured | 2023-04-20 16:13:50.258 NDT [49] LOG: checkpoint starting: shutdown immediate
ferretdb_postgres_secured | 2023-04-20 16:13:50.370 NDT [49] LOG: checkpoint complete: wrote 918 buffers (5.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.059 s, sync=0.044 s, total=0.115 s; sync files=250, longest=0.009 s, average=0.001 s; distance=4217 kB, estimate=4217 kB
ferretdb_postgres_secured | 2023-04-20 16:13:50.393 NDT [48] LOG: database system is shut down
ferretdb_postgres_secured | done
ferretdb_postgres_secured | server stopped
ferretdb_postgres_secured |
ferretdb_postgres_secured | PostgreSQL init process complete; ready for start up.
ferretdb_postgres_secured |
ferretdb_postgres_secured | 2023-04-20 16:13:50.653 NDT [1] LOG: starting PostgreSQL 15.2 (Debian 15.2-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
ferretdb_postgres_secured | 2023-04-20 16:13:50.659 NDT [1] LOG: listening on IPv4 address "0.0.0.0", port 5432
ferretdb_postgres_secured | 2023-04-20 16:13:50.659 NDT [1] LOG: listening on IPv6 address "::", port 5432
ferretdb_postgres_secured | 2023-04-20 16:13:50.685 NDT [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
ferretdb_postgres_secured | 2023-04-20 16:13:50.728 NDT [64] LOG: database system was shut down at 2023-04-20 16:13:50 NDT
ferretdb_postgres_secured | 2023-04-20 16:13:50.760 NDT [1] LOG: database system is ready to accept connections
ferretdb_postgres | ********************************************************************************
ferretdb_postgres | WARNING: POSTGRES_HOST_AUTH_METHOD has been set to "trust". This will allow
ferretdb_postgres | anyone with access to the Postgres port to access your database without
ferretdb_postgres | a password, even if POSTGRES_PASSWORD is set. See PostgreSQL
ferretdb_postgres | documentation about "trust":
ferretdb_postgres | https://www.postgresql.org/docs/current/auth-trust.html
ferretdb_postgres | In Docker's default configuration, this is effectively any other
ferretdb_postgres | container on the same system.
ferretdb_postgres |
ferretdb_postgres | It is not recommended to use POSTGRES_HOST_AUTH_METHOD=trust. Replace
ferretdb_postgres | it with "-e POSTGRES_PASSWORD=password" instead to set a password in
ferretdb_postgres | "docker run".
ferretdb_postgres | ********************************************************************************
ferretdb_postgres | The files belonging to this database system will be owned by user "postgres".
ferretdb_postgres | This user must also own the server process.
ferretdb_postgres |
ferretdb_postgres | The database cluster will be initialized with locale "en_US.utf8".
ferretdb_postgres | The default database encoding has accordingly been set to "UTF8".
ferretdb_postgres | The default text search configuration will be set to "english".
ferretdb_postgres |
ferretdb_postgres | Data page checksums are disabled.
ferretdb_postgres |
ferretdb_postgres | fixing permissions on existing directory /var/lib/postgresql/data ... ok
ferretdb_postgres | creating subdirectories ... ok
ferretdb_postgres | selecting dynamic shared memory implementation ... posix
ferretdb_postgres | selecting default max_connections ... 100
ferretdb_postgres | selecting default shared_buffers ... 128MB
ferretdb_postgres | selecting default time zone ... America/St_Johns
ferretdb_postgres | creating configuration files ... ok
ferretdb_postgres | running bootstrap script ... ok
ferretdb_postgres | performing post-bootstrap initialization ... ok
ferretdb_jaeger | {"level":"info","ts":1682016228.630337,"caller":"grpc@v1.54.0/clientconn.go:1231","msg":"[core][Channel #3 SubChannel #4] Subchannel picks a new address ":14250" to connect","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6308553,"caller":"grpc/builder.go:113","msg":"Checking connection to collector"}
ferretdb_jaeger | {"level":"info","ts":1682016228.630899,"caller":"grpc/builder.go:124","msg":"Agent collector connection state change","dialTarget":":14250","status":"CONNECTING"}
ferretdb_jaeger | {"level":"info","ts":1682016228.6337135,"caller":"./main.go:256","msg":"Starting agent"}
ferretdb_jaeger | {"level":"info","ts":1682016228.633833,"caller":"querysvc/query_service.go:134","msg":"Archive storage not created","reason":"archive storage not supported"}
ferretdb_jaeger | {"level":"info","ts":1682016228.6339045,"caller":"app/flags.go:141","msg":"Archive storage not initialized"}
ferretdb_jaeger | {"level":"info","ts":1682016228.6341965,"caller":"grpc@v1.54.0/clientconn.go:1117","msg":"[core][Channel #3 SubChannel #4] Subchannel Connectivity change to READY","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.634411,"caller":"grpc@v1.54.0/server.go:632","msg":"[core][Server #7] Server created","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.634085,"caller":"app/agent.go:69","msg":"Starting jaeger-agent HTTP server","http-port":5778}
ferretdb_jaeger | {"level":"info","ts":1682016228.6346133,"caller":"base/balancer.go:177","msg":"[roundrobin]roundrobinPicker: Build called with info: {map[0xc00055e630:{{\n "Addr": ":14250",\n "ServerName": "",\n "Attributes": null,\n "BalancerAttributes": null,\n "Type": 0,\n "Metadata": null\n}}]}","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6348042,"caller":"grpc@v1.54.0/clientconn.go:428","msg":"[core][Channel #3] Channel Connectivity change to READY","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.634846,"caller":"grpc/builder.go:124","msg":"Agent collector connection state change","dialTarget":":14250","status":"READY"}
ferretdb_jaeger | {"level":"info","ts":1682016228.634707,"caller":"grpc@v1.54.0/clientconn.go:105","msg":"[core][Channel #8] Channel created","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6355574,"caller":"grpc@v1.54.0/clientconn.go:1569","msg":"[core][Channel #8] original dial target is: ":16685"","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.635603,"caller":"grpc@v1.54.0/clientconn.go:1574","msg":"[core][Channel #8] dial target ":16685" parse failed: parse ":16685": missing protocol scheme","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6356533,"caller":"grpc@v1.54.0/clientconn.go:1589","msg":"[core][Channel #8] fallback to scheme "passthrough"","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6357577,"caller":"grpc@v1.54.0/clientconn.go:1597","msg":"[core][Channel #8] parsed dial target is: {Scheme:passthrough Authority: URL:{Scheme:passthrough Opaque: User: Host: Path:/:16685 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6357849,"caller":"grpc@v1.54.0/clientconn.go:273","msg":"[core][Channel #8] Channel authority set to "localhost:16685"","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6358705,"caller":"grpc@v1.54.0/resolver_conn_wrapper.go:175","msg":"[core][Channel #8] Resolver state updated: {\n "Addresses": [\n {\n "Addr": ":16685",\n "ServerName": "",\n "Attributes": null,\n "BalancerAttributes": null,\n "Type": 0,\n "Metadata": null\n }\n ],\n "ServiceConfig": null,\n "Attributes": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6359317,"caller":"grpc@v1.54.0/balancer_conn_wrappers.go:274","msg":"[core][Channel #8] Channel switches to new LB policy "pick_first"","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.635983,"caller":"grpc@v1.54.0/balancer_conn_wrappers.go:306","msg":"[core][Channel #8 SubChannel #9] Subchannel created","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.636037,"caller":"grpc@v1.54.0/clientconn.go:428","msg":"[core][Channel #8] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6361043,"caller":"grpc@v1.54.0/clientconn.go:1117","msg":"[core][Channel #8 SubChannel #9] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6361752,"caller":"grpc@v1.54.0/clientconn.go:1231","msg":"[core][Channel #8 SubChannel #9] Subchannel picks a new address ":16685" to connect","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"warn","ts":1682016228.6366057,"caller":"grpc@v1.54.0/clientconn.go:1292","msg":"[core][Channel #8 SubChannel #9] grpc: addrConn.createTransport failed to connect to {\n "Addr": ":16685",\n "ServerName": "localhost:16685",\n "Attributes": null,\n "BalancerAttributes": null,\n "Type": 0,\n "Metadata": null\n}. Err: connection error: desc = "transport: Error while dialing: dial tcp :16685: connect: connection refused"","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.636682,"caller":"grpc@v1.54.0/clientconn.go:1119","msg":"[core][Channel #8 SubChannel #9] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: Error while dialing: dial tcp :16685: connect: connection refused"","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6367838,"caller":"grpc@v1.54.0/clientconn.go:428","msg":"[core][Channel #8] Channel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6380706,"caller":"app/server.go:215","msg":"Query server started","http_addr":"[::]:16686","grpc_addr":"[::]:16685"}
ferretdb_jaeger | {"level":"info","ts":1682016228.6381311,"caller":"healthcheck/handler.go:129","msg":"Health Check state change","status":"ready"}
ferretdb_jaeger | {"level":"info","ts":1682016228.6381679,"caller":"app/server.go:298","msg":"Starting GRPC server","port":16685,"addr":":16685"}
ferretdb_jaeger | {"level":"info","ts":1682016228.6382346,"caller":"grpc@v1.54.0/server.go:820","msg":"[core][Server #7 ListenSocket #10] ListenSocket created","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016228.6383805,"caller":"app/server.go:279","msg":"Starting HTTP server","port":16686,"addr":":16686"}
ferretdb_jaeger | {"level":"info","ts":1682016229.6378992,"caller":"grpc@v1.54.0/clientconn.go:1119","msg":"[core][Channel #8 SubChannel #9] Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: Error while dialing: dial tcp :16685: connect: connection refused"","system":"grpc","grpc_log":true}
ferretdb_jaeger | {"level":"info","ts":1682016229.638026,"caller":"grpc@v1.54.0/clientconn.go:428","msg":"[core][Channel #8] Channel Connectivity change to IDLE","system":"grpc","grpc_log":true}
ferretdb_postgres | syncing data to disk ... ok
ferretdb_postgres |
ferretdb_postgres |
ferretdb_postgres | Success. You can now start the database server using:
ferretdb_postgres |
ferretdb_postgres | pg_ctl -D /var/lib/postgresql/data -l logfile start
ferretdb_postgres |
ferretdb_postgres | initdb: warning: enabling "trust" authentication for local connections
ferretdb_postgres | initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
ferretdb_postgres | waiting for server to start....2023-04-20 16:13:54.478 NDT [49] LOG: starting PostgreSQL 15.2 (Debian 15.2-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
ferretdb_postgres | 2023-04-20 16:13:54.480 NDT [49] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
ferretdb_postgres | 2023-04-20 16:13:54.489 NDT [52] LOG: database system was shut down at 2023-04-20 16:13:53 NDT
ferretdb_postgres | 2023-04-20 16:13:54.501 NDT [49] LOG: database system is ready to accept connections
ferretdb_postgres | done
ferretdb_postgres | server started
ferretdb_postgres | CREATE DATABASE
ferretdb_postgres |
ferretdb_postgres |
ferretdb_postgres | /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
ferretdb_postgres |
ferretdb_postgres | waiting for server to shut down....2023-04-20 16:13:55.233 NDT [49] LOG: received fast shutdown request
ferretdb_postgres | 2023-04-20 16:13:55.237 NDT [49] LOG: aborting any active transactions
ferretdb_postgres | 2023-04-20 16:13:55.242 NDT [49] LOG: background worker "logical replication launcher" (PID 55) exited with exit code 1
ferretdb_postgres | 2023-04-20 16:13:55.254 NDT [50] LOG: shutting down
ferretdb_postgres | 2023-04-20 16:13:55.258 NDT [50] LOG: checkpoint starting: shutdown immediate
ferretdb_postgres | 2023-04-20 16:13:55.351 NDT [50] LOG: checkpoint complete: wrote 918 buffers (5.6%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.061 s, sync=0.019 s, total=0.097 s; sync files=250, longest=0.005 s, average=0.001 s; distance=4217 kB, estimate=4217 kB
ferretdb_postgres | 2023-04-20 16:13:55.369 NDT [49] LOG: database system is shut down
ferretdb_postgres | done
ferretdb_postgres | server stopped
ferretdb_postgres |
ferretdb_postgres | PostgreSQL init process complete; ready for start up.
ferretdb_postgres |
ferretdb_postgres | 2023-04-20 16:13:55.577 NDT [1] LOG: starting PostgreSQL 15.2 (Debian 15.2-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
ferretdb_postgres | 2023-04-20 16:13:55.580 NDT [1] LOG: listening on IPv4 address "0.0.0.0", port 5432
ferretdb_postgres | 2023-04-20 16:13:55.589 NDT [1] LOG: listening on IPv6 address "::", port 5432
ferretdb_postgres | 2023-04-20 16:13:55.605 NDT [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
ferretdb_postgres | 2023-04-20 16:13:55.620 NDT [65] LOG: database system was shut down at 2023-04-20 16:13:55 NDT
ferretdb_postgres | 2023-04-20 16:13:55.634 NDT [1] LOG: database system is ready to accept connections
ferretdb_mongodb_secured | /usr/local/bin/docker-entrypoint.sh: line 416: 45 Illegal instruction (core dumped) "${mongodHackedArgs[@]}" --fork
ferretdb_mongodb_secured exited with code 132
ferretdb_mongodb exited with code 132
ferretdb_postgres_secured | 2023-04-20 16:18:50.860 NDT [62] LOG: checkpoint starting: time
ferretdb_postgres_secured | 2023-04-20 16:18:55.007 NDT [62] LOG: checkpoint complete: wrote 44 buffers (0.3%); 0 WAL file(s) added, 0 removed, 0 recycled; write=4.122 s, sync=0.006 s, total=4.181 s; sync files=12, longest=0.003 s, average=0.001 s; distance=252 kB, estimate=252 kB
ferretdb_postgres | 2023-04-20 16:18:55.717 NDT [63] LOG: checkpoint starting: time
ferretdb_postgres | 2023-04-20 16:18:57.950 NDT [63] LOG: checkpoint complete: wrote 25 buffers (0.2%); 0 WAL file(s) added, 0 removed, 0 recycled; write=2.214 s, sync=0.007 s, total=2.233 s; sync files=11, longest=0.005 s, average=0.001 s; distance=65 kB, estimate=65 kB

</details>

[AlekSi]

Both setupAnyPostgres and setupAnyTigris miss if ctx.Err() != nil { return ctx.Err() } check after those for loops. Could you contribute a fix?

[syasyayas]

Sure!