POSTGRES_PASS no longer appears to be read with version sha256:b700342c925bc42e33fd39d5907a9f7e179906b1d13e26b7084987c18f020b85

[favna]

What is the bug or the crash?

Today I pruned all my docker images to start fresh as I was debugging an unrelated issue and I noticed that after pulling a fresh copy of kartoza/postgis:latest that I was no longer able to connect to the database. After getting the SHA256 of the image from one of my colleagues, starting that and then comparing the logging between the 2 I noticed that the default password that we set through POSTGRES_PASS in our Docker compose file is no longer being used by kartoza/postgis.

Specifically, for sha256:b700342c925bc42e33fd39d5907a9f7e179906b1d13e26b7084987c18f020b85 the logs begin with:

Creating /settings directory
Creating /docker-entrypoint-initdb.d directory
Creating /ssl_certificates directory
Add rule to pg_hba: 0.0.0.0/0
Add rule to pg_hba: replication replicator
 _  __          _                  ____             _
| |/ /__ _ _ __| |_ ___ ______ _  |  _ \  ___   ___| | _____ _ __
| ' // _` | '__| __/ _ \_  / _` | | | | |/ _ \ / __| |/ / _ \ '__|
| . \ (_| | |  | || (_) / / (_| | | |_| | (_) | (__|   <  __/ |
|_|\_\__,_|_|   \__\___/___\__,_| |____/ \___/ \___|_|\_\___|_|
 ____           _    ____ ___ ____
|  _ \ ___  ___| |_ / ___|_ _/ ___|
| |_) / _ \/ __| __| |  _ | |\___ \
|  __/ (_) \__ \ |_| |_| || | ___) |
|_|   \___/|___/\__|\____|___|____/
[Entrypoint] GENERATED Replication  PASSWORD:  apNDtJdvwjpTlpDigX3z70
[Entrypoint] Setup master database
Creating /opt/archivedir directory
/var/run/postgresql:5432 - no response
2025-01-09 08:27:39.495 UTC [112] LOG:  starting PostgreSQL 17.2 (Debian 17.2-1.pgdg120+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
2025-01-09 08:27:39.495 UTC [112] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2025-01-09 08:27:39.496 UTC [112] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2025-01-09 08:27:39.498 UTC [119] LOG:  database system was shut down at 2024-12-17 20:28:59 UTC
2025-01-09 08:27:39.500 UTC [112] LOG:  database system is ready to accept connections
2025-01-09 08:27:39.502 UTC [122] FATAL:  database "developmentdb" does not exist
2025-01-09 08:27:39.502 UTC [112] LOG:  background worker "pg_cron launcher" (PID 122) exited with exit code 1
2025-01-09 08:27:40.506 UTC [127] FATAL:  database "developmentdb" does not exist
2025-01-09 08:27:40.508 UTC [112] LOG:  background worker "pg_cron launcher" (PID 127) exited with exit code 1
/var/run/postgresql:5432 - accepting connections
postgres ready
Creating user developmentdb
 [Entrypoint] Creating/Updating user  developmentdb
CREATE ROLE
Creating user replicator
 [Entrypoint] Creating/Updating user  replicator
CREATE ROLE
 [Entrypoint] Create database  developmentdb
CREATE EXTENSION
 [Entrypoint] Enabling extension  postgis  in the database :  developmentdb
CREATE EXTENSION
 [Entrypoint] Enabling extension  hstore  in the database :  developmentdb
CREATE EXTENSION
 [Entrypoint] Enabling extension  postgis_topology  in the database :  developmentdb
CREATE EXTENSION
 [Entrypoint] Enabling extension  postgis_raster  in the database :  developmentdb
CREATE EXTENSION
 [Entrypoint] Enabling extension  pgrouting  in the database :  developmentdb
CREATE EXTENSION
 [Entrypoint] loading legacy sql in database  developmentdb
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE OPERATOR CLASS
 [Entrypoint] Create database  test
NOTICE:  extension "pg_cron" already exists, skipping
CREATE EXTENSION
 [Entrypoint] Enabling extension  postgis  in the database :  test
CREATE EXTENSION
 [Entrypoint] Enabling extension  hstore  in the database :  test
CREATE EXTENSION
 [Entrypoint] Enabling extension  postgis_topology  in the database :  test
CREATE EXTENSION
 [Entrypoint] Enabling extension  postgis_raster  in the database :  test
CREATE EXTENSION
 [Entrypoint] Enabling extension  pgrouting  in the database :  test
CREATE EXTENSION
 [Entrypoint] loading legacy sql in database  test
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
2025-01-09 08:27:41.512 UTC [204] LOG:  pg_cron scheduler started
CREATE OPERATOR CLASS
                                                 List of databases
   Name    |  Owner   | Encoding | Locale Provider | Collate |  Ctype  | Locale
| ICU Rules |   Access privileges
-----------+----------+----------+-----------------+---------+---------+--------
+-----------+-----------------------
 developmentdb   | developmentdb  | UTF8     | libc            | C.UTF-8 | C.UTF-8 |
|           |
 postgres  | postgres | UTF8     | libc            | C.UTF-8 | C.UTF-8 |
|           |
 template0 | postgres | UTF8     | libc            | C.UTF-8 | C.UTF-8 |
|           | =c/postgres          +
           |          |          |                 |         |         |
|           | postgres=CTc/postgres
 template1 | postgres | UTF8     | libc            | C.UTF-8 | C.UTF-8 |
|           | =c/postgres          +
           |          |          |                 |         |         |
|           | postgres=CTc/postgres
 test      | developmentdb  | UTF8     | libc            | C.UTF-8 | C.UTF-8 |
|           |
(5 rows)

Whereas for sha256:1360f5d3dcb2de05e8f6ced767e26a5f29344876a9ef119f1a3a69c9583eceda they begin with:

Creating /settings directory
Creating /ssl_certificates directory
Add rule to pg_hba: 0.0.0.0/0
Add rule to pg_hba: replication replicator
 _  __          _                  ____             _
| |/ /__ _ _ __| |_ ___ ______ _  |  _ \  ___   ___| | _____ _ __
| ' // _` | '__| __/ _ \_  / _` | | | | |/ _ \ / __| |/ / _ \ '__|
| . \ (_| | |  | || (_) / / (_| | | |_| | (_) | (__|   <  __/ |
|_|\_\__,_|_|   \__\___/___\__,_| |____/ \___/ \___|_|\_\___|_|
 ____           _    ____ ___ ____
|  _ \ ___  ___| |_ / ___|_ _/ ___|
| |_) / _ \/ __| __| |  _ | |\___ \
|  __/ (_) \__ \ |_| |_| || | ___) |
|_|   \___/|___/\__|\____|___|____/
[Entrypoint] GENERATED Postgres  PASSWORD:  developmentdb
 PGPASSWORD Generated above:
Setup master database
Creating /opt/archivedir directory
2025-01-09 08:59:13.863 UTC [72] LOG:  starting PostgreSQL 13.3 (Debian 13.3-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2025-01-09 08:59:13.865 UTC [72] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2025-01-09 08:59:13.867 UTC [72] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2025-01-09 08:59:13.875 UTC [76] LOG:  database system was shut down at 2021-06-27 17:37:41 UTC
2025-01-09 08:59:13.884 UTC [72] LOG:  database system is ready to accept connections
2025-01-09 08:59:13.888 UTC [82] FATAL:  database "developmentdb" does not exist
2025-01-09 08:59:13.891 UTC [72] LOG:  background worker "pg_cron launcher" (PID 82) exited with exit code 1
/var/run/postgresql:5432 - accepting connections
postgres ready
Creating superuser developmentdb
CREATE ROLE
Creating replication user replicator
CREATE ROLE
2025-01-09 08:59:14.897 UTC [179] FATAL:  database "developmentdb" does not exist
2025-01-09 08:59:14.901 UTC [72] LOG:  background worker "pg_cron launcher" (PID 179) exited with exit code 1
Create db developmentdb
Enabling "postgis" in the database developmentdb
CREATE EXTENSION
Enabling "hstore" in the database developmentdb
CREATE EXTENSION
Enabling "postgis_topology" in the database developmentdb
2025-01-09 08:59:15.914 UTC [221] LOG:  pg_cron scheduler started
CREATE EXTENSION
Enabling "postgis_raster" in the database developmentdb
CREATE EXTENSION
Enabling "pgrouting" in the database developmentdb
CREATE EXTENSION
Loading legacy sql
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE OPERATOR CLASS
ALTER DEFAULT PRIVILEGES
Create db test
Enabling "postgis" in the database test
CREATE EXTENSION
Enabling "hstore" in the database test
CREATE EXTENSION
Enabling "postgis_topology" in the database test
CREATE EXTENSION
Enabling "postgis_raster" in the database test
CREATE EXTENSION
Enabling "pgrouting" in the database test
CREATE EXTENSION
Loading legacy sql
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE FUNCTION
CREATE OPERATOR CLASS
ALTER DEFAULT PRIVILEGES
CREATE EXTENSION
                              List of databases
   Name    |  Owner   | Encoding | Collate |  Ctype  |   Access privileges
-----------+----------+----------+---------+---------+-----------------------
 developmentdb   | developmentdb  | UTF8     | C.UTF-8 | C.UTF-8 |
 postgres  | postgres | UTF8     | C.UTF-8 | C.UTF-8 |
 template0 | postgres | UTF8     | C.UTF-8 | C.UTF-8 | =c/postgres          +
           |          |          |         |         | postgres=CTc/postgres
 template1 | postgres | UTF8     | C.UTF-8 | C.UTF-8 | =c/postgres          +
           |          |          |         |         | postgres=CTc/postgres
 test      | developmentdb  | UTF8     | C.UTF-8 | C.UTF-8 |
(5 rows)
2025-01-09 08:59:20.276 UTC [72] LOG:  received smart shutdown request
2025-01-09 08:59:20.278 UTC [221] LOG:  pg_cron scheduler shutting down
2025-01-09 08:59:20.281 UTC [72] LOG:  background worker "logical replication launcher" (PID 83) exited with exit code 1
2025-01-09 08:59:20.283 UTC [77] LOG:  shutting down
/var/run/postgresql/13-main.pid
2025-01-09 08:59:20.405 UTC [72] LOG:  database system is shut down
Postgres initialisation process completed .... restarting in foreground
2025-01-09 08:59:21.437 UTC [517] LOG:  starting PostgreSQL 13.3 (Debian 13.3-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2025-01-09 08:59:21.439 UTC [517] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2025-01-09 08:59:21.439 UTC [517] LOG:  listening on IPv6 address "::", port 5432
2025-01-09 08:59:21.441 UTC [517] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2025-01-09 08:59:21.448 UTC [519] LOG:  database system was shut down at 2025-01-09 08:59:20 UTC
2025-01-09 08:59:21.455 UTC [517] LOG:  database system is ready to accept connections
2025-01-09 08:59:21.478 UTC [525] LOG:  pg_cron scheduler started

Note the difference in the line [Entrypoint] GENERATED Replication PASSWORD:

Steps to reproduce the issue

1. Pull kartoza/postgis:latest, or more specifically, kartoza/postgis:latest@sha256:b700342c925bc42e33fd39d5907a9f7e179906b1d13e26b7084987c18f020b85
2. Run the docker container with docker run -d --name postgres -e POSTGRES_USER=developmentdb -e POSTGRES_PASS=developmentdb -e POSTGRES_DBNAME=developmentdb kartoza/postgis:latest
3. Inspect the logs with docker logs -f -t postgres
4. Note that the custom provided password is not being used

Versions

kartoza/postgis -> sha256:b700342c925bc42e33fd39d5907a9f7e179906b1d13e26b7084987c18f020b85

Additional context

I replicated this issue on an M4 Pro equipped Macbook (arm64) and on an Inteli7-11850H equipped Kubuntu 22.04 Linux laptop (amd64)

[NyakudyaA]

@favna If you login to the database can you not execute the shell with the given password?. Showing the password in the logs was disabled for security reasons. Maybe in future, we could have something like
SHOW_CREDENTRIALS_IN_LOGS=FALSE and then a user can set this to show the replication, postgres pass depending on their choice

[favna]

I cannot login with my own provided credentials either. I have not yet tried to login with the password from the logs, I'll try that tomorrow (this is for work and it's past work hours for me now)

[NyakudyaA]

@favna i did try step 2 and inside the container I can log into the database. The replication password should in fact only show if replication is being setup.

[favna]

I have managed to reproduce the issue in a smaller repro.

1. Add a docker-compose.yml file with content:

services:
  postgres:
    cap_add:
      - SYS_RESOURCE
    container_name: postgres
    image: kartoza/postgis:latest
    deploy:
      resources:
        limits:
          memory: 2G
    ports:
      - "5432:5432"
    restart: unless-stopped
    tty: true
    environment:
      - POSTGRES_USER=developmentdb
      - POSTGRES_PASS=developmentdb
      - POSTGRES_DBNAME=developmentdb

2. Run this container: docker compose up -d
3. Try to connect with psql --port=5432 --username=developmentdb --host=localhost --dbname=developmentdb --password
4. Provide developmentdb as password
5. Observe error:

psql: error: connection to server at "localhost" (::1), port 5432 failed: server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.

6. Now remove tty: true from the yaml:

services:
  postgres:
    cap_add:
      - SYS_RESOURCE
    container_name: postgres
    image: kartoza/postgis:latest
    deploy:
      resources:
        limits:
          memory: 2G
    ports:
      - "5432:5432"
    restart: unless-stopped
-    tty: true
    environment:
      - POSTGRES_USER=developmentdb
      - POSTGRES_PASS=developmentdb
      - POSTGRES_DBNAME=developmentdb

7. Run docker compose down -v to clean the old state
8. Run docker compose up -d again
9. Try to connect with psql --port=5432 --username=developmentdb --host=localhost --dbname=developmentdb --password
10. Provide developmentdb as password
11. It works!

So it appears the issue is somehow related to tty: true. Notably, the docker run equivalent of this would be

docker run --detach \
  --cap-add=SYS_RESOURCE \
  --interactive \
  --tty \
  --name=postgres \
  --memory=2g \
  --publish 5432:5432 \
  --restart unless-stopped \
  --env POSTGRES_USER=developmentdb \
  --env POSTGRES_PASS=developmentdb \
  --env POSTGRES_DBNAME=developmentdb \
  kartoza/postgis:latest

Which does work.

This is quite strange, because docker-compose should map 1:1 to docker run in this case. The only difference that comes to mind is that docker compose by default creates an additional network (test_default in my case since my folder is called test) but that really shouldn't matter.