Postgres not actually up when initialization script is run on a new container image, not accepting connections.

[JeffGradyAtMolarCo]

Hi, all. My team has been using postgres:latest for a couple months and we're setting up our db user and credentials etc. via a bash script called database_setup.sh in /docker-entrypoint-initdb.d/.

In the past couple days, this seems to have stopped working. The exact failure mode seems to be that our initialization script is being run when postgres claims to be up, but isn't accepting connections as far as psql can tell:

% docker logs -f d99a893ceb7e
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with locale "en_US.utf8".
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".

Data page checksums are disabled.

fixing permissions on existing directory /var/lib/postgresql/data ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Etc/UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
syncing data to disk ... ok


Success. You can now start the database server using:

    pg_ctl -D /var/lib/postgresql/data -l logfile start

initdb: warning: enabling "trust" authentication for local connections
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.
waiting for server to start....2022-03-08 14:34:38.124 UTC [49] LOG:  starting PostgreSQL 14.2 (Debian 14.2-1.pgdg110+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2022-03-08 14:34:38.126 UTC [49] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-03-08 14:34:38.129 UTC [50] LOG:  database system was shut down at 2022-03-08 14:34:37 UTC
2022-03-08 14:34:38.132 UTC [49] LOG:  database system is ready to accept connections
 done
server started

/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/database_setup.sh
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?

PostgreSQL Database directory appears to contain a database; Skipping initialization

2022-03-08 14:34:38.679 UTC [1] LOG:  starting PostgreSQL 14.2 (Debian 14.2-1.pgdg110+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2022-03-08 14:34:38.679 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2022-03-08 14:34:38.679 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2022-03-08 14:34:38.681 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-03-08 14:34:38.686 UTC [28] LOG:  database system was interrupted; last known up at 2022-03-08 14:34:38 UTC
2022-03-08 14:34:38.779 UTC [28] LOG:  database system was not properly shut down; automatic recovery in progress
2022-03-08 14:34:38.782 UTC [28] LOG:  invalid record length at 0/16FAE80: wanted 24, got 0
2022-03-08 14:34:38.782 UTC [28] LOG:  redo is not required
2022-03-08 14:34:38.789 UTC [1] LOG:  database system is ready to accept connections

The important part in the above log is:

/usr/local/bin/docker-entrypoint.sh: running /docker-entrypoint-initdb.d/database_setup.sh
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?
psql: error: connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
connection to server at "localhost" (::1), port 5432 failed: Cannot assign requested address
	Is the server running on that host and accepting TCP/IP connections?

Our db init script isn't doing anything exotic:

...
export PGUSER=postgres
export PGDATABASE=postgres

psql -c "CREATE USER $APP_DATABASE_USER WITH PASSWORD '$APP_DATABASE_PASSWORD'";
psql -c "CREATE DATABASE $APP_DATABASE_NAME";
psql -c "GRANT ALL PRIVILEGES ON DATABASE $APP_DATABASE_NAME TO $APP_DATABASE_USER";
psql -c "ALTER USER $APP_DATABASE_USER CREATEDB";

Here's our docker-compose.yml entry for postgres:

  postgres:
    restart: always
    image: postgres:latest
    ports:
      - "5432:5432"
    volumes:
      - ./postgres/bin/database_setup.sh:/docker-entrypoint-initdb.d/database_setup.sh
    environment:
      PGHOST: "localhost"
    env_file:
      - .env
    healthcheck:
      test: [ "CMD-SHELL", "pg_isready -U postgres" ]
      interval: 5s
      timeout: 5s
      retries: 5

Any thoughts as to what's going on?

[JeffGradyAtMolarCo]

For now, this seems to be a valid workaround for me (in docker-compse.yml):

    environment:
      - PGHOST=/var/run/postgresql
      - PGPORT=5432

The server is answering on the unix socket, just not via TCP.

[yosifkit]

I'm not sure what would've changed in the past couple days; we haven't changed how the temporary server in the entrypoint has been run for 2+ years:

https://github.com/docker-library/postgres/blame/d80a8db9e33723c4674c529168a0d4bb8f68ffb6/docker-entrypoint.sh#L257-L270

---

As far as what has changed in the past months, latest did move from 13 to 14 about 5 months ago, so perhaps that transition caused the issue? I'd definitely recommend picking a PostgreSQL major instead of latest since upgrading from one major to another is not automatic.

[JeffGradyAtMolarCo]

does not listen on external TCP/IP and waits until start finishes on this line is interesting:

https://github.com/docker-library/postgres/blame/d80a8db9e33723c4674c529168a0d4bb8f68ffb6/docker-entrypoint.sh#L263

That makes me wonder how our setup .sh script ever worked.

Did anything change about when /docker-entrypoint-initdb.d/ scripts run? If they originally ran after TCP listening happened and that changed, that could cause the behavior I'm seeing.

We've taken your advice and pinned to a major version.

I'm still seeing weird behavior when I shell into the container and run our .sh manually. Sometimes the changes seem to persist, sometimes not.

[jjakob]

You can use the docker_process_sql function in your initdb.d scripts. It's defined in the entrypoint script.

postgres/14/alpine/docker-entrypoint.sh

Lines 185 to 197 in d80a8db

	# Execute sql script, passed via stdin (or -f flag of pqsl)
	# usage: docker_process_sql [psql-cli-args]
	# ie: docker_process_sql --dbname=mydb <<<'INSERT ...'
	# ie: docker_process_sql -f my-file.sql
	# ie: docker_process_sql <my-file.sql
	docker_process_sql() {
	local query_runner=( psql -v ON_ERROR_STOP=1 --username "$POSTGRES_USER" --no-password --no-psqlrc )
	if [ -n "$POSTGRES_DB" ]; then
	query_runner+=( --dbname "$POSTGRES_DB" )
	fi
	PGHOST= PGHOSTADDR= "${query_runner[@]}" "$@"
	}

Your initdb.d .sh script must not be executable, or it will not get sourced into the entrypoint script (where docker_process_sql is defined) but forked by the shell as a separate process.

postgres/14/alpine/docker-entrypoint.sh

Lines 164 to 173 in d80a8db

	*.sh)
	# https://github.com/docker-library/postgres/issues/450#issuecomment-393167936
	# https://github.com/docker-library/postgres/pull/452
	if [ -x "$f" ]; then
	echo "$0: running $f"
	"$f"
	else
	echo "$0: sourcing $f"
	. "$f"
	fi

Example:

docker_process_sql <<-'EOSQL'
CREATE ROLE "myuser" WITH LOGIN PASSWORD "mypassword";
EOSQL

or pass variables to psql:

docker_process_sql -v non_root_user="$POSTGRES_NON_ROOT_USER" -v non_root_password="$POSTGRES_NON_ROOT_PASSWORD" <<-'EOSQL'
CREATE ROLE :"non_root_user" WITH LOGIN PASSWORD :'non_root_password';
EOSQL

[tianon]

Going to close as this appears to be as solved as it is going to be 😇 ❤️

For further help, I'd suggest a dedicated support forum, such as the Docker Community Forums, the Docker Community Slack, or Stack Overflow. 👍

[sepsol]

For now, this seems to be a valid workaround for me (in docker-compse.yml):

    environment:
      - PGHOST=/var/run/postgresql
      - PGPORT=5432

The server is answering on the unix socket, just not via TCP.

You don't know how much digging I had to do to find this answer. It should've been stated more clearly. The current README states:

https://github.com/docker-library/docs/blob/8e1967957fe52f9cdf7a222fd658341fd76c6feb/postgres/README.md?plain=1#L244

Granted, there is a very small mention of the issue in the last sentence, but it doesn't make it obvious by providing an example of unsetting host envs or by clearly stating that you have to set PGHOST to /var/run/postgresql for it to work.