PostgreSQL: background worker "logical replication launcher" exited with exit code 1

Question

Using our own instance of Gitlab we get the error background worker "logical replication launcher" exited with exit code 1 when trying to use the postgres service in our runners. Haven't found anything useful over the internet. Any idea what's going on?

Versions:

• Gitlab 12.4.3
• gitlab-runner 12.5.0 (limit of 4 concurrent jobs)
• postgres 12.1 (tried with 11 and same result)
• DigitalOcean droplet: CPU-Optimized / 8 GB / 4 vCPUs

Relevant part in gitlab-ci.yml:

image: golang:1.12

services:
  - postgres

variables:
  POSTGRES_USER: postgres
  POSTGRES_DB: xproject_test
  POSTGRES_PASSWORD: postgres

Failure log:

Running with gitlab-runner 12.5.0 (577f813d)
  on xproject sEZeszwx
Using Docker executor with image xproject-ci ...
Starting service postgres:latest ...
Pulling docker image postgres:latest ...
Using docker image sha256:9eb7b0ce936d2eac8150df3de7496067d56bf4c1957404525fd60c3640dfd450 for postgres:latest ...
Waiting for services to be up and running...

*** WARNING: Service runner-sEZeszwx-project-18-concurrent-0-postgres-0 probably didn't start properly.

Health check error:
service "runner-sEZeszwx-project-18-concurrent-0-postgres-0-wait-for-service" timeout

Health check container logs:


Service container logs:
2019-11-20T10:16:23.805738908Z The files belonging to this database system will be owned by user "postgres".
2019-11-20T10:16:23.805807212Z This user must also own the server process.
2019-11-20T10:16:23.805818432Z 
2019-11-20T10:16:23.806094094Z The database cluster will be initialized with locale "en_US.utf8".
2019-11-20T10:16:23.806120707Z The default database encoding has accordingly been set to "UTF8".
2019-11-20T10:16:23.806208494Z The default text search configuration will be set to "english".
2019-11-20T10:16:23.806264704Z 
2019-11-20T10:16:23.806282587Z Data page checksums are disabled.
2019-11-20T10:16:23.806586302Z 
2019-11-20T10:16:23.806931287Z fixing permissions on existing directory /var/lib/postgresql/data ... ok
2019-11-20T10:16:23.807763042Z creating subdirectories ... ok
2019-11-20T10:16:23.808045789Z selecting dynamic shared memory implementation ... posix
2019-11-20T10:16:23.835644353Z selecting default max_connections ... 100
2019-11-20T10:16:23.866604734Z selecting default shared_buffers ... 128MB
2019-11-20T10:16:23.928432088Z selecting default time zone ... Etc/UTC
2019-11-20T10:16:23.929447992Z creating configuration files ... ok
2019-11-20T10:16:24.122662589Z running bootstrap script ... ok
2019-11-20T10:16:24.706975030Z performing post-bootstrap initialization ... ok
2019-11-20T10:16:24.819117668Z initdb: warning: enabling "trust" authentication for local connections
2019-11-20T10:16:24.819150100Z You can change this by editing pg_hba.conf or using the option -A, or
2019-11-20T10:16:24.819157763Z --auth-local and --auth-host, the next time you run initdb.
2019-11-20T10:16:24.819272849Z syncing data to disk ... ok
2019-11-20T10:16:24.819313390Z 
2019-11-20T10:16:24.819328954Z 
2019-11-20T10:16:24.819340787Z Success. You can now start the database server using:
2019-11-20T10:16:24.819349374Z 
2019-11-20T10:16:24.819357407Z     pg_ctl -D /var/lib/postgresql/data -l logfile start
2019-11-20T10:16:24.819365840Z 
2019-11-20T10:16:24.857656160Z waiting for server to start....2019-11-20 10:16:24.857 UTC [46] LOG:  starting PostgreSQL 12.1 (Debian 12.1-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
2019-11-20T10:16:24.860371378Z 2019-11-20 10:16:24.860 UTC [46] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2019-11-20T10:16:24.886271885Z 2019-11-20 10:16:24.886 UTC [47] LOG:  database system was shut down at 2019-11-20 10:16:24 UTC
2019-11-20T10:16:24.892844968Z 2019-11-20 10:16:24.892 UTC [46] LOG:  database system is ready to accept connections
2019-11-20T10:16:24.943542403Z  done
2019-11-20T10:16:24.943591286Z server started
2019-11-20T10:16:25.084670051Z CREATE DATABASE
2019-11-20T10:16:25.086153670Z 
2019-11-20T10:16:25.086604000Z 
2019-11-20T10:16:25.086694058Z /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
2019-11-20T10:16:25.086711933Z 
2019-11-20T10:16:25.088473308Z 2019-11-20 10:16:25.088 UTC [46] LOG:  received fast shutdown request
2019-11-20T10:16:25.090893184Z waiting for server to shut down....2019-11-20 10:16:25.090 UTC [46] LOG:  aborting any active transactions
2019-11-20T10:16:25.092499368Z 2019-11-20 10:16:25.092 UTC [46] LOG:  background worker "logical replication launcher" (PID 53) exited with exit code 1
2019-11-20T10:16:25.093942785Z 2019-11-20 10:16:25.093 UTC [48] LOG:  shutting down
2019-11-20T10:16:25.112341160Z 2019-11-20 10:16:25.112 UTC [46] LOG:  database system is shut down
2019-11-20T10:16:25.189351710Z  done
2019-11-20T10:16:25.189393803Z server stopped
2019-11-20T10:16:25.189929555Z 
2019-11-20T10:16:25.189967760Z PostgreSQL init process complete; ready for start up.
2019-11-20T10:16:25.189982340Z 
2019-11-20T10:16:25.214046388Z 2019-11-20 10:16:25.213 UTC [1] LOG:  starting PostgreSQL 12.1 (Debian 12.1-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
2019-11-20T10:16:25.214092434Z 2019-11-20 10:16:25.213 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2019-11-20T10:16:25.214172706Z 2019-11-20 10:16:25.214 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2019-11-20T10:16:25.219769380Z 2019-11-20 10:16:25.219 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2019-11-20T10:16:25.241614800Z 2019-11-20 10:16:25.241 UTC [64] LOG:  database system was shut down at 2019-11-20 10:16:25 UTC
2019-11-20T10:16:25.248887712Z 2019-11-20 10:16:25.248 UTC [1] LOG:  database system is ready to accept connections

*********

Solution 1

Ended up rebooting the machine where gitlab was installed and that solved the issue. No idea of why the service was giving a timeout and printing the misleading log.

Related issue for having a better health check with docker: https://gitlab.com/gitlab-org/gitlab-runner/issues/3984

Update 15/02/2021

Generating TLS certificates with docker dind seems to fix the issue. You would need privileged runners and the dind service in your .gitlab-ci.yml:

services:
  - docker:dind

Solution 2

First thing, your Database container is ready to accept the connection, as you can see from the logs

2019-11-20T10:16:25.248887712Z 2019-11-20 10:16:25.248 UTC [1] LOG:  database system is ready to accept connections

This is the expected behaviour of the offical Postgres image If you look into the entrypoint of Postgres it performs two tasks.

• it will run any *.sql files, run any executable *.sh scripts, and source any non-executable *.sh scripts found in that directory to do further initialization before starting the service from this directory /docker-entrypoint-initdb.d
• after initialization completion, it stops the process and runs it again as the main process of the container.

do you know why I get that shutdown request?

# stop postgresql server after done setting up user and running scripts
docker_temp_server_stop() {
    PGUSER="${PGUSER:-postgres}" \
    pg_ctl -D "$PGDATA" -m fast -w stop
}

then after completion

.
.

            echo 'PostgreSQL init process complete; ready for start up.'

.
.
exec "$@"

Solution 3

That error is just a harmless consequence of the "fast shutdown request" that PostgreSQL received.

Comments

[Mario Pérez Alarcón]

do you know why I get that shutdown request?

[Laurenz Albe]

No idea. PostgreSQL received a SIGINT. But obviously it got started again.

[Mario Pérez Alarcón]

it got started but it couldn't connect dial tcp 172.17.0.3:5432: connect: connection refused :/

[Mario Pérez Alarcón]

Thank you Adiii, it got started but couldn't connect to the database, got this from the app code dial tcp 172.17.0.3:5432: connect: connection refused

[Adiii]

seems like you app starting before the DB container able to accept the connection. add order mean first launch DB container then the app, or you can explore wait-for-it on app side.github.com/vishnubob/wait-for-it

[Mario Pérez Alarcón]

I don't receive that log nor that warning when the job runs fine, currently it appears randomly and the issue may be with gitlab-runner.

[Mario Pérez Alarcón]

thanks for link, that even if it solves I feel is a patch, I never had to wait for the service and everything was working until one of the dependencies were updated, maybe gitlab or gitlab-runner. As mentioned in other comment this log/warning doesn't appear when the job runs fine

[Mario Pérez Alarcón]

I found there is a wait_for_services_timeout config at: docs.gitlab.com/runner/configuration/… Increased to 200 but same result

[Adiii]

I will suggest to run it with gitlab runner, just use simple docker-compose and then verify, just break the problem.