22

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

*********
Laurenz Albe
  • 209,280
  • 17
  • 206
  • 263
Mario Pérez Alarcón
  • 3,468
  • 2
  • 27
  • 38

4 Answers4

13

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 "$@"
Adiii
  • 54,482
  • 7
  • 145
  • 148
  • 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` – Mario Pérez Alarcón Nov 20 '19 at 14:47
  • 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.https://github.com/vishnubob/wait-for-it – Adiii Nov 20 '19 at 14:51
  • 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 Nov 21 '19 at 08:49
  • I found there is a `wait_for_services_timeout` config at: https://docs.gitlab.com/runner/configuration/advanced-configuration.html#the-runnersdocker-section Increased to 200 but same result – Mario Pérez Alarcón Nov 21 '19 at 09:36
  • 1
    I will suggest to run it with gitlab runner, just use simple docker-compose and then verify, just break the problem. – Adiii Nov 21 '19 at 09:38
10

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

Laurenz Albe
  • 209,280
  • 17
  • 206
  • 263
0

That is not an ERROR, that is a LOG. This is normal when a database shuts down. It is questionable why this is worth logging (of course the launcher is going to shut down when the database shuts down) and maybe it will be silenced in some future version. But it does not indicate any kind of problem.

If you have another question, please ask it in another question.

jjanes
  • 37,812
  • 5
  • 27
  • 34
0

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
Mario Pérez Alarcón
  • 3,468
  • 2
  • 27
  • 38