Postgres LOG: invalid length of startup packet

[meena-erian]

Steps to reproduce:

Run docker-compose up in a folder containing the following docker-compose.yml

version: '3.2'
services:
  db:
    image: postgres:10
    ports: 
      - "5432:5432"
    environment:
      - POSTGRES_DB=admin
      - POSTGRES_PASSWORD=admin
      - POSTGRES_USER=admin
      - PGDATA=/var/lib/postgresql/data/pgdata

What I was expecting:

That the postgres image will work as it used to (This same docker compose file used to work just fine until recently)

What happens:

I'm unable to connect to the postgresql server and every time I try to establish a tcp connection with the server, it doesn't respond and it repeats the error: invalid length of startup packet

Host OS: Tested on Windows 11 and Ubuntu 20 linux, same results

Output of docker-compose up

[+] Running 2/2
 - Network postgres_default  Created                                                                                                      0.6s
 - Container postgres_db_1   Created                                                                                                      0.2s
Attaching to db_1
db_1  | The files belonging to this database system will be owned by user "postgres".
db_1  | This user must also own the server process.
db_1  | 
db_1  | The database cluster will be initialized with locale "en_US.utf8".
db_1  | The default database encoding has accordingly been set to "UTF8".
db_1  | The default text search configuration will be set to "english".
db_1  | 
db_1  | Data page checksums are disabled.
db_1  |
db_1  | fixing permissions on existing directory /var/lib/postgresql/data/pgdata ... ok
db_1  | creating subdirectories ... ok
db_1  | selecting default max_connections ... 100
db_1  | selecting default shared_buffers ... 128MB
db_1  | selecting default timezone ... Etc/UTC
db_1  | selecting dynamic shared memory implementation ... posix
db_1  | creating configuration files ... ok
db_1  | running bootstrap script ... ok
db_1  | performing post-bootstrap initialization ... ok
db_1  | syncing data to disk ... 
db_1  | WARNING: enabling "trust" authentication for local connections
db_1  | You can change this by editing pg_hba.conf or using the option -A, or
db_1  | --auth-local and --auth-host, the next time you run initdb.
db_1  | ok
db_1  |
db_1  | Success. You can now start the database server using:
db_1  |
db_1  |     pg_ctl -D /var/lib/postgresql/data/pgdata -l logfile start
db_1  |
db_1  | waiting for server to start....2021-09-27 13:19:45.798 UTC [49] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db_1  | 2021-09-27 13:19:45.820 UTC [50] LOG:  database system was shut down at 2021-09-27 13:19:45 UTC
db_1  | 2021-09-27 13:19:45.826 UTC [49] LOG:  database system is ready to accept connections
db_1  |  done
db_1  | server started
db_1  | CREATE DATABASE
db_1  | 
db_1  |
db_1  | /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
db_1  |
db_1  | 2021-09-27 13:19:46.361 UTC [49] LOG:  received fast shutdown request
db_1  | waiting for server to shut down....2021-09-27 13:19:46.365 UTC [49] LOG:  aborting any active transactions
db_1  | 2021-09-27 13:19:46.367 UTC [49] LOG:  worker process: logical replication launcher (PID 56) exited with exit code 1
db_1  | 2021-09-27 13:19:46.368 UTC [51] LOG:  shutting down
db_1  | 2021-09-27 13:19:46.387 UTC [49] LOG:  database system is shut down
db_1  |  done
db_1  | server stopped
db_1  |
db_1  | PostgreSQL init process complete; ready for start up.
db_1  |
db_1  | 2021-09-27 13:19:46.478 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
db_1  | 2021-09-27 13:19:46.478 UTC [1] LOG:  listening on IPv6 address "::", port 5432
db_1  | 2021-09-27 13:19:46.485 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db_1  | 2021-09-27 13:19:46.508 UTC [77] LOG:  database system was shut down at 2021-09-27 13:19:46 UTC
db_1  | 2021-09-27 13:19:46.525 UTC [1] LOG:  database system is ready to accept connections
db_1  | 2021-09-27 13:19:59.992 UTC [85] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:19:59.997 UTC [84] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:00.003 UTC [86] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:01.232 UTC [87] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:01.235 UTC [88] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:01.242 UTC [89] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:06.276 UTC [91] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:06.279 UTC [90] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:06.286 UTC [92] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:36.334 UTC [94] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:36.339 UTC [93] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:20:36.536 UTC [95] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:21:36.574 UTC [97] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:21:36.579 UTC [98] LOG:  invalid length of startup packet
db_1  | 2021-09-27 13:21:36.587 UTC [99] LOG:  invalid length of startup packet

image JSON

[
    {
        "Id": "sha256:630f5b9a1a00d26975cd4fda3464af0829bbfb1f21c1e30238fec7c11eed609d",
        "RepoTags": [
            "postgres:10"
        ],
        "RepoDigests": [
            "postgres@sha256:0c0efe2cf407036a3d2cf06bc2bcba4aab8dbbd3f9ab4d02d88994a3fec60165"
        ],
        "Parent": "",
        "Comment": "",
        "Created": "2021-09-03T13:00:46.671004011Z",
        "Container": "b2e5027d0e5944b47caabfc04106c9dd537079de60272c10c45b7c7f9f270e41",
        "ContainerConfig": {
            "Hostname": "b2e5027d0e59",
            "Domainname": "",
            "User": "",
            "AttachStdin": false,
            "AttachStdout": false,
            "AttachStderr": false,
            "ExposedPorts": {
                "5432/tcp": {}
            },
            "Tty": false,
            "OpenStdin": false,
            "StdinOnce": false,
            "Env": [
                "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/lib/postgresql/10/bin",
                "GOSU_VERSION=1.12",
                "LANG=en_US.utf8",
                "PG_MAJOR=10",
                "PG_VERSION=10.18-1.pgdg90+1",
                "PGDATA=/var/lib/postgresql/data"
            ],
            "Cmd": [
                "/bin/sh",
                "-c",
                "#(nop) ",
                "CMD [\"postgres\"]"
            ],
            "Image": "sha256:e2d76eadec842fdc416f7bc372bd7cac7eb8d9efec33d5d4c1d31f2b7a2e71c5",
            "Volumes": {
                "/var/lib/postgresql/data": {}
            },
            "WorkingDir": "",
            "Entrypoint": [
                "docker-entrypoint.sh"
            ],
            "OnBuild": null,
            "Labels": {},
            "StopSignal": "SIGINT"
        },
        "DockerVersion": "20.10.7",
        "Author": "",
        "Config": {
            "Hostname": "",
            "Domainname": "",
            "User": "",
            "AttachStdin": false,
            "AttachStdout": false,
            "AttachStderr": false,
            "ExposedPorts": {
                "5432/tcp": {}
            },
            "Tty": false,
            "OpenStdin": false,
            "StdinOnce": false,
            "Env": [
                "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/lib/postgresql/10/bin",
                "GOSU_VERSION=1.12",
                "LANG=en_US.utf8",
                "PG_MAJOR=10",
                "PG_VERSION=10.18-1.pgdg90+1",
                "PGDATA=/var/lib/postgresql/data"
            ],
            "Cmd": [
                "postgres"
            ],
            "Image": "sha256:e2d76eadec842fdc416f7bc372bd7cac7eb8d9efec33d5d4c1d31f2b7a2e71c5",
            "Volumes": {
                "/var/lib/postgresql/data": {}
            },
            "WorkingDir": "",
            "Entrypoint": [
                "docker-entrypoint.sh"
            ],
            "OnBuild": null,
            "Labels": null,
            "StopSignal": "SIGINT"
        },
        "Architecture": "amd64",
        "Os": "linux",
        "Size": 199926548,
        "VirtualSize": 199926548,
        "GraphDriver": {
            "Data": {
                "LowerDir": "/var/lib/docker/overlay2/7a88e942ddc19f63d0a79f1bb207dda4616a11c29b28d8cc746b78105bc70439/diff:/var/lib/docker/overlay2/200eec67ade02401260ed142d53fbcdbaa73ad5e105b5710a0d3db57fc4cde6c/diff:/var/lib/docker/overlay2/2ef24fa6edf7f5942b365b31087baf17572325d008a34dc0f20b8eacd421bdc3/diff:/var/lib/docker/overlay2/0c04b6ae223c24e0db3da41d17d03c4dca4009d82723735ab0a97646d9ea3295/diff:/var/lib/docker/overlay2/2bbc104b5ce0b372a02c4ce3a4025224a8dfc2a1355fd2481fd4e9b9cbd70506/diff:/var/lib/docker/overlay2/acb67ddc77d2fad2d90ce2dc4c84d7c893c7e1bcf90d3f27df61d5811fbbedf0/diff:/var/lib/docker/overlay2/5d122efbddb9de6a939ad6fed029202eb61a474d1c3aee6cb047e2a0edb28de8/diff:/var/lib/docker/overlay2/09b055414434a439437e15c164b3b51d9ba334a663beca645cccbd5a7fbe7415/diff:/var/lib/docker/overlay2/69b6e4e65d8c343fcf52e3033cf8c069ac3a41634df08aae537c0741f56b6e67/diff:/var/lib/docker/overlay2/db2cdb789f845aa24594ead3e600d42f81f66f1ab463d72b93c1265d52ed897f/diff:/var/lib/docker/overlay2/c03587a60211319e3ad2c4fd26f6d14cfa1db903bf6f76904a4fa6ba15dfdba0/diff:/var/lib/docker/overlay2/85af4c5b35f2a94fe5ed624dea58200212ba2fd0b221e8a9a814ce515a993cd3/diff:/var/lib/docker/overlay2/63181deac7d8aa49a8be09e1fb32ac207d15d2ca351eabf2c645e5269c7e7b78/diff",
                "MergedDir": "/var/lib/docker/overlay2/d8c51a5dd7a1e905093101fe1ff4cd943328d015672d1d5f0ab1a389f12ef367/merged",
                "UpperDir": "/var/lib/docker/overlay2/d8c51a5dd7a1e905093101fe1ff4cd943328d015672d1d5f0ab1a389f12ef367/diff",
                "WorkDir": "/var/lib/docker/overlay2/d8c51a5dd7a1e905093101fe1ff4cd943328d015672d1d5f0ab1a389f12ef367/work"
            },
            "Name": "overlay2"
        },
        "RootFS": {
            "Type": "layers",
            "Layers": [
                "sha256:12ef3c2ef0384e327d25d29edf73902296040ac49b203f95becaea2e59f243cf",
                "sha256:0fcf361a68d5f2d3159ea90ecdac9b368959eae01541bfb4e5ab3530318e8102",
                "sha256:22ceb6c9395f91675f59ac95113d3598dfa79ecbb92e1b02a40bb9fd342cab25",
                "sha256:04cf050c997411d156c00c0f8d9557d8e7b5a96e312f88df4d5f49f1886b5519",
                "sha256:04724e1cada4e02d14f9f30592816717c0bb2aadca12e13ea61a23b8aee6f8aa",
                "sha256:9fbd66797e4daf0f49bb2deb2357126a01b0ec750a3bb5ae577d8801e36c6fca",
                "sha256:8d6f92659e117b4ce24d3b148521285e103adb9852d0d7f50ef197cac6c82487",
                "sha256:1687a175f8121dad588be6d743221848d99df222cadf9b451576d8c26703f7ed",
                "sha256:d6a0679db5791fb8f4aab4cad3934d66cd1b2206bc708068017443bb6d03dd39",
                "sha256:68211f5360fd85ce51446508b4425512ab91c9ab0b3eb6633a55b93a8b09f284",
                "sha256:14e3f16d80fb64a074ffb753b9586fcec03c7a489e9fe74939b2382fbc248670",
                "sha256:d33322c652c3067d8c2123ac893417b622a851ed76cd774ac335002d794e3aea",
                "sha256:01ddadddaea6e557cc2d566596e9376caae2eccddd1b860a66730e18a980a325",
                "sha256:d74dfd82cd0e2a5f7d96d68dec9042c9887250a0aaff6ce0ff0a26bbd928ecde"
            ]
        },
        "Metadata": {
            "LastTagTime": "0001-01-01T00:00:00Z"
        }
    }
]

[wglambert]

Is the container behind any ingress, loadbalancer, or proxy?

[meena-erian]

Nope, it's only docker. It's driving me crazy because this same exact docker project used to work fine everywhere now it's not working anywhere!

[wglambert]

Yeah I imagine it's something with the host's environment. Weird that you get it on Windows and Linux, but I'm not able to reproduce the error

$ docker-compose up -d
Creating network "root_default" with the default driver
Pulling db (postgres:10)...
10: Pulling from library/postgres
36d925ed8e30: Pull complete
c8b0099cd1a0: Pull complete
0bf2a548fff2: Pull complete
36e6fa05828b: Pull complete
000ab621c968: Pull complete
6855b4b63497: Pull complete
9201c39bd813: Pull complete
de19e180543b: Pull complete
b25ce2d23845: Pull complete
9a1621c579ee: Pull complete
ef3f0fd3ca11: Pull complete
f5442c57fe0c: Pull complete
72221f0ea2ce: Pull complete
432032c2a5e6: Pull complete
Digest: sha256:0ce09036f7fbaa27ab91863d8941555fc089a80ada45e1970f10a3d830d38f21
Status: Downloaded newer image for postgres:10
Creating root_db_1 ... done

$ docker ps
CONTAINER ID   IMAGE         COMMAND                  CREATED         STATUS         PORTS                    NAMES
e16ce605e533   postgres:10   "docker-entrypoint.s…"   4 minutes ago   Up 4 minutes   0.0.0.0:5432->5432/tcp   root_db_1

$ psql -h 127.0.0.1 -U admin
Password for user admin: 
psql (12.8, server 10.18 (Debian 10.18-1.pgdg90+1))
Type "help" for help.

admin=# exit

$ docker-compose logs | tail -n 5
db_1  | 2021-09-28 18:21:27.575 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
db_1  | 2021-09-28 18:21:27.577 UTC [1] LOG:  listening on IPv6 address "::", port 5432
db_1  | 2021-09-28 18:21:27.580 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db_1  | 2021-09-28 18:21:27.602 UTC [76] LOG:  database system was shut down at 2021-09-28 18:21:27 UTC
db_1  | 2021-09-28 18:21:27.611 UTC [1] LOG:  database system is ready to accept connections

You could also try asking over at the Docker Community Forums, Docker Community Slack, or Stack Overflow

[meena-erian]

Nevermind, I'm still not sure what's going on but it's probably me

[Martinsos]

Experiencing similar problem here: wasp-lang/wasp#460 .

Seems related to MIT-LCP/mimic-code#684 .

[LegationPro]

I've had the same error output when trying to connect to a PSQL server.
What helped me was changing the host from 172.28.128.1 to 0.0.0.0

[runatyr1]

For me this was solved by adding this to .helmignore:
templates/tests/
Also disabled the liveliness and readiness probes for the deployment (kuberentes).
Not sure if both are needed but I don't want to start making a lot of tests to figure that out at this moment, happy enough that it works :)
It looks like either or both the helm test pod or the deployment probes were sending malformed packets to the db and it got scared and shut down.

[liyaodev]

@meena-erian I think we have encountered the same problem, docker-compose run postgres, do you solve it?

This phenomenon occurs after running for a period of time, and can be recovered by restarting.

[meena-erian]

@liyaodev Sorry for the late reply. I ended up trying different image tags until I found a build that worked fine and I locked it. I would share with you the exact tag but it's too hard to trace back in which project I encountered this. Fortunately, most of my recent projects uses much more recent versions of Postgress and everything is working fine.

[liyaodev]

@meena-erian Thank you very much for your reply. I haven't solved it yet. What is the latest version you said? The version I'm using postgres:12.16. Thanks agin.

[meena-erian]

@liyaodev Very welcome! In most of my current projects, I'm using postgres:13.4 and haven't faced any problems so far

[liyaodev]

@liyaodev Very welcome! In most of my current projects, I'm using postgres:13.4 and haven't faced any problems so far

That's great, I'll give it a try, thanks.