serverpod create testpod fails 80% of the time

[lukehutch]

serverpod create testpod fails 80% of the time with:

Setting up Docker and default database tables in /home/luke/Work/testpod/testpod_server
If you run serverpod create for the first time, this can take a few minutes as Docker is downloading the images for Postgres. If you get stuck at this
step, make sure that you have the latest version of Docker Desktop and that it is currently running.

Starting docker
Recreating testpod_server_postgres_1 ... 
Recreating testpod_server_redis_1    ... 
Recreating testpod_server_postgres_1 ... done
Recreating testpod_server_redis_1    ... done
Postgres is ready
Creating testpod_server_postgres_run ... 
Creating testpod_server_postgres_run ... done
psql: error: connection to server at "postgres" (172.21.0.3), port 5432 failed: FATAL:  password authentication failed for user "postgres"
2
Stopping docker
Stopping testpod_server_postgres_1 ... 
Stopping testpod_server_redis_1    ... 
Stopping testpod_server_postgres_1 ... done
Stopping testpod_server_redis_1    ... done
Completed table setup exit code: 0
Cleaning up

It seems to be a race condition though, because I have had it succeed on the odd occasion. If this happens, then the testpod server can't connect to posgres: #521

[yahu1031]

@lukehutch Can you please remove unwanted volumes in docker and try again?

[lukehutch]

I shut down all Docker instances each time before running serverpod create testpod. Most of the time the command fails. Occasionally it succeeds. I now have a successful testpod so I'll start development from that one.

[vlidholt]

@lukehutch, can you provide a bit more information on what platform you are using. Can you also run serverpod version and paste the output.

[lukehutch]

$ serverpod version
Serverpod version: 0.9.21
$ uname -a
Linux fedora 6.0.7-200.fc36.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Nov 3 17:09:02 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

[vlidholt]

Thank you. Perhaps the docker image on Linux opens the port for Postgres before its fully configured. A hack could be to add a short pause after the Postgres port is available. I'll give that a shot.

[hermann-o]

The issue exists in Version 1 and is actually a feature of the postgres docker. Read more here: docker-library/postgres#203
At the end of the day ... to set a new postgres password, you need to remove not only the docker container, but also all volumes as well.
Steps to reproduce:

1. run "serverpod create mypod" on a native environment -> OK
2. rm -rf mypod ; docker stop mypod* ; docker rm mypod;
3. repeat 1. -> FATAL: password authentication failed for user "postgres
4. repeat 2, docker volume rm ...
5. repeat 1 -> OK

[yahu1031]

@lukehutch Can you please remove unwanted volumes in docker and try again?

@hermann-o Yes, I have been through here once and twice. Will update the script soon.

[services-it-city]

After running the command, an error occurs:

root@server:~# serverpod create mypod
Creating project mypod.
  /root/mypod/mypod_server/docker-compose.yaml
  /root/mypod/mypod_server/generated/tables-serverpod.pgsql
  /root/mypod/mypod_server/generated/tables.pgsql
  /root/mypod/mypod_server/generated/protocol.yaml

........

 Volume "mypod_server_mypod_data"  Creating
 Volume "mypod_server_mypod_data"  Created
 Container mypod_server-postgres-1  Creating
 Container mypod_server-redis-1  Creating
 Container mypod_server-postgres-1  Created
 Container mypod_server-redis-1  Created
 Container mypod_server-redis-1  Starting
 Container mypod_server-postgres-1  Starting
 Container mypod_server-postgres-1  Started
 Container mypod_server-redis-1  Started
/usr/bin/netstat
Postgres is ready
psql: error: connection to server at "postgres" (172.18.0.2), port 5432 failed: Connection refused
	Is the server running on that host and accepting TCP/IP connections?
Stopping docker
 Container mypod_server-redis-1  Stopping
 Container mypod_server-postgres-1  Stopping
 Container mypod_server-redis-1  Stopped
 Container mypod_server-postgres-1  Stopped
Completed table setup exit code: 0
Cleaning up


SERVERPOD CREATED 🥳

All setup. You are ready to rock!

Start your Serverpod by running:

  $ cd mypod/mypod_server
  $ docker compose up --build --detach
  $ dart bin/main.dart

root@server:~# 

My configuration 1 (Installation Result: Fatal):
OS: Ubuntu Server 22.04
ServerPod: 1.1.0
Docker: 23.0.5

My configuration 2 (Installation Result: Fatal):
OS: Ubuntu Server 22.04
ServerPod: 1.1.0
Docker: 20.10.21

My configuration 3 (Installation Result: Fatal):
OS: Ubuntu Server 22.04
ServerPod: 1.0.1
Docker: 23.0.5

My configuration 4 (Installation Result: Fatal):
OS: Ubuntu Server 22.04
ServerPod: 1.0.1
Docker: 20.10.21

My configuration 5 (Installation Result: Successful):
OS: Ubuntu Server 22.04
ServerPod: 1.0.0
Docker: 23.0.5

My configuration 6 (Installation Result: Successful):
OS: Ubuntu Server 22.04
ServerPod: 1.0.0
Docker: 20.10.21

My configuration 7 (Installation Result: Fatal):
HW: MAckBook Pro 16 M1
OS: MacOS Ventura
ServerPod: 1.1.0
Docker: 23.0.5

Everyone has the same error. No opportunity to test this interesting product (((

[Isakdl]

@lukehutch Are you still encountering this issue?

[lukehutch]

@Isakdl I'm not sure, I got it working once and moved on. I just tried running serverpod generate testpod again, and I can't seem to get past `Downloading and configuring Docker image -- it just sits there counting up the seconds.

[Isakdl]

@lukehutch Alright, yes I think what is happening there is that you are running into a connection error and we have no timeout here right now. If you run the command with -v it should print all output.

[lukehutch]

@Isakdl OK, I got it to hang again with -v (the first time it worked fine, which is not shown in the log, but the second time it failed, which is shown below):

✓ Getting Flutter app package dependencies. (2.2s)
⠙ Creating default database migration.... (0ms)
Creating initial migration.
✓ Creating default database migration. (0.2s)
⠙ Downloading and configuring Docker image.... (0ms)
Applying default migration.
Starting docker container.
 Container testpod_server-redis-1  Recreate
 Container testpod_server-postgres-1  Recreate
 Container testpod_server-postgres-1  Recreated
 Container testpod_server-redis-1  Recreated
 Container testpod_server-redis-1  Starting
 Container testpod_server-postgres-1  Starting
 Container testpod_server-redis-1  Started
 Container testpod_server-postgres-1  Started
Waiting for database to become available.
Applying migrations.
SERVERPOD version: 1.1.0, dart: 3.3.0-91.0.dev (dev) (Thu Nov 2 09:10:03 2023 -0700) on "linux_x64", time: 2023-12-07 02:34:24.319318Z
mode: development, role: maintenance, logging: verbose, serverId: default
Config loaded from: config/development.yaml
api port: 8080
api public host: localhost
api public port: 8080
api public scheme: http
insights port: 8081
insights public host: localhost
insights public port: 8081
insights public scheme: http
web port: 8082
web public host: localhost
web public port: 8082
web public scheme: http
database host: localhost
database port: 8090
database name: testpod
database user: postgres
database require SSL: false
database unix socket: false
database pass: ********
redis host: localhost
redis port: 8091
redis pass: ********

Failed to connect to the database. Retrying in 10 seconds. PostgreSQLSeverity.fatal 28P01: password authentication failed for user "postgres" 
===== asynchronous gap ===========================
package:postgres_pool/postgres_pool.dart 351:18               PgPool.run.<fn>
package:retry/retry.dart 131:16                               RetryOptions.retry
package:postgres_pool/postgres_pool.dart 349:14               PgPool.run
package:serverpod/src/database/database_connection.dart 42:5  DatabaseConnection.testConnection
package:serverpod/src/server/serverpod.dart 620:9             Serverpod._connectToDatabase
package:serverpod/src/server/serverpod.dart 348:21            Serverpod.start.<fn>
package:serverpod/src/server/serverpod.dart 341:5             Serverpod.start
package:testpod_server/server.dart 33:3                       run

Database configuration:
database host: localhost
database port: 8090
database name: testpod
database user: postgres
database require SSL: false
database unix socket: false
database pass: ********

Failed to connect to the database. Retrying in 10 seconds. PostgreSQLSeverity.fatal 28P01: password authentication failed for user "postgres" 
===== asynchronous gap ===========================
package:postgres_pool/postgres_pool.dart 351:18               PgPool.run.<fn>
package:retry/retry.dart 131:16                               RetryOptions.retry
package:postgres_pool/postgres_pool.dart 349:14               PgPool.run
package:serverpod/src/database/database_connection.dart 42:5  DatabaseConnection.testConnection
package:serverpod/src/server/serverpod.dart 620:9             Serverpod._connectToDatabase
package:serverpod/src/server/serverpod.dart 348:21            Serverpod.start.<fn>
package:serverpod/src/server/serverpod.dart 341:5             Serverpod.start
package:testpod_server/server.dart 33:3                       run

Failed to connect to the database. Retrying in 10 seconds. PostgreSQLSeverity.fatal 28P01: password authentication failed for user "postgres" 
===== asynchronous gap ===========================
package:postgres_pool/postgres_pool.dart 351:18               PgPool.run.<fn>
package:retry/retry.dart 131:16                               RetryOptions.retry
package:postgres_pool/postgres_pool.dart 349:14               PgPool.run
package:serverpod/src/database/database_connection.dart 42:5  DatabaseConnection.testConnection
package:serverpod/src/server/serverpod.dart 620:9             Serverpod._connectToDatabase
package:serverpod/src/server/serverpod.dart 348:21            Serverpod.start.<fn>
package:serverpod/src/server/serverpod.dart 341:5             Serverpod.start
package:testpod_server/server.dart 33:3                       run

Failed to connect to the database. Retrying in 10 seconds. PostgreSQLSeverity.fatal 28P01: password authentication failed for user "postgres" 
===== asynchronous gap ===========================
package:postgres_pool/postgres_pool.dart 351:18               PgPool.run.<fn>
package:retry/retry.dart 131:16                               RetryOptions.retry
package:postgres_pool/postgres_pool.dart 349:14               PgPool.run
package:serverpod/src/database/database_connection.dart 42:5  DatabaseConnection.testConnection
package:serverpod/src/server/serverpod.dart 620:9             Serverpod._connectToDatabase
package:serverpod/src/server/serverpod.dart 348:21            Serverpod.start.<fn>
package:serverpod/src/server/serverpod.dart 341:5             Serverpod.start
package:testpod_server/server.dart 33:3                       run

[Isakdl]

@lukehutch Thank you.

I think I know what is going on, you ran the command twice with the same project name, right? Since we create a docker container with a volume in the create command, you would have to clean up the volume since it contains the random generated password from the previous create command.

Therefor it is now unable to connect on the second try. Now this is of course not great we have to give a proper error here, and secondly we are trying to connect to the database an infinite amount of times but we should have a timeout so we can bail.

[lukehutch]

Yes, I did, and this makes sense.