"threads.c" error when running binaries or docker image for amd64 devel version #3569

laurenceisla · 2024-06-03T18:23:46Z

Environment

PostgreSQL version: PostgreSQL 15.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.3.0, 64-bit
PostgREST version: v12.1 (devel)
PostgREST docker version: devel
Operating system: NixOS 23.11

Description of issue

Executing the binary or docker release for the devel branch , returns an error when trying to connect to the database.

Local binary:

PGRST_DB_URI=postgres://postgres@localhost:5432/postgres \
PGRST_DB_ANON_ROLE=postgres \
PGRST_DB_LOG_LEVEL=info \
./postgrest

03/Jun/2024:13:19:01 -0500: Starting PostgREST 12.1...
03/Jun/2024:13:19:01 -0500: Listening on port 3000
03/Jun/2024:13:19:01 -0500: Attempting to connect to the database...
Assertion failed: *(&once->n) != 4 (threads.c: k5_once: 564)
fish: Job 1, 'PGRST_DB_URI=postgres://postgre…' terminated by signal PGRST_DB_ANON_ROLE=postgres \ (PGRST_DB_LOG_LEVEL=info \)
fish: Job ./postgrest, 'SIGABRT' terminated by signal Abort ()

Docker:

sudo docker run --net=host --rm --name test-db-conn -p 3000:3000 \
            -e PGRST_DB_URI="postgres://postgres@localhost:5432/postgres" \
            -e PGRST_DB_ANON_ROLE="postgres" \
            -e PGRST_LOG_LEVEL="info" \
            postgrest/postgrest:devel

03/Jun/2024:18:21:03 +0000: Starting PostgREST 12.1...
03/Jun/2024:18:21:03 +0000: Listening on port 3000
03/Jun/2024:18:21:03 +0000: Attempting to connect to the database...
Assertion failed: *(&once->n) != 4 (threads.c: k5_once: 564)

Running the main branch from a Nix environment does not return this error:

PGRST_DB_URI=postgres://postgres@localhost:5432/postgres \
PGRST_DB_ANON_ROLE=postgres \
PGRST_DB_LOG_LEVEL=info \
postgrest-run

03/Jun/2024:13:18:45 -0500: Starting PostgREST 12.1 (b6c6f2b)...
03/Jun/2024:13:18:45 -0500: Attempting to connect to the database...
03/Jun/2024:13:18:45 -0500: Listening on port 3000
03/Jun/2024:13:18:45 -0500: Successfully connected to PostgreSQL 15.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.3.0, 64-bit
...

The text was updated successfully, but these errors were encountered:

steve-chavez · 2024-06-03T18:40:23Z

Local binary:

PGRST_DB_URI=postgres://postgres@localhost:5432/postgres \
PGRST_DB_ANON_ROLE=postgres \
PGRST_DB_LOG_LEVEL=info \
postgrest-run

There seems to be a mistake above, postgrest-run doesn't work but I can reproduce with the binary. Like so:

PGRST_DB_URI=postgres://postgres@localhost:5432/postgres \
PGRST_DB_ANON_ROLE=postgres \
PGRST_DB_LOG_LEVEL=info \
./postgrest

03/Jun/2024:13:40:53 -0500: Starting PostgREST 12.1...
03/Jun/2024:13:40:53 -0500: Listening on port 3000
03/Jun/2024:13:40:53 -0500: Attempting to connect to the database...
Assertion failed: *(&once->n) != 4 (threads.c: k5_once: 564)
Aborted (core dumped)

Edit: Corrected the issue description.

wolfgangwalther · 2024-06-03T18:40:24Z

So, essentially you are saying that the static build fails to run, right?

Can't reproduce, yet:

PGRST_DB_LOG_LEVEL=info postgrest-with-postgresql-15 /nix/store/7c9y713ayzvj1812bhiac38f0wkvvcfv-postgrest-static-x86_64-unknown-linux-musl-12.1/bin/postgrest
postgrest-with-postgresql-15: You can connect with: psql 'postgres:///postgres?host=/run/user/1000/postgrest/postgrest-with-postgresql-15-2tR/socket' -U postgres
postgrest-with-postgresql-15: You can tail the logs with: tail -f /run/user/1000/postgrest/postgrest-with-postgresql-15-2tR/db.log
03/Jun/2024:20:39:36 +0200: Starting PostgREST 12.1...
03/Jun/2024:20:39:36 +0200: Attempting to connect to the database...
03/Jun/2024:20:39:36 +0200: Listening on port 3000
03/Jun/2024:20:39:36 +0200: Listening for notifications on the "pgrst" channel
03/Jun/2024:20:39:36 +0200: Successfully connected to PostgreSQL 15.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 13.2.0, 64-bit
03/Jun/2024:20:39:36 +0200: Config reloaded
03/Jun/2024:20:39:36 +0200: Schema cache queried in 1.9 milliseconds
03/Jun/2024:20:39:36 +0200: Schema cache loaded 0 Relations, 0 Relationships, 0 Functions, 0 Domain Representations, 4 Media Type Handlers

Can't reproduce by downloading the binary either.

wolfgangwalther · 2024-06-03T18:48:16Z

Can reproduce with the downloaded binary and a local PG (non nix tooled)

PGRST_DB_LOG_LEVEL=info PGRST_DB_URI=postgres://postgres@localhost:5432/postgres PGRST_DB_ANON_ROLE=postgres ./postgrest
03/Jun/2024:20:46:46 +0200: Starting PostgREST 12.1...
03/Jun/2024:20:46:46 +0200: Listening on port 3000
03/Jun/2024:20:46:46 +0200: Attempting to connect to the database...
Assertion failed: *(&once->n) != 4 (threads.c: k5_once: 564)
[1]    1424861 IOT instruction (core dumped)  PGRST_DB_LOG_LEVEL=info PGRST_DB_URI= PGRST_DB_ANON_ROLE=postgres ./postgrest

And with the fresh build of nix-build -A postgrestStatic as well:

PGRST_DB_LOG_LEVEL=info PGRST_DB_URI=postgres://postgres@localhost:5432/postgres PGRST_DB_ANON_ROLE=postgres /nix/store/7c9y713ayzvj1812bhiac38f0wkvvcfv-postgrest-static-x86_64-unknown-linux-musl-12.1/bin/postgrest
03/Jun/2024:20:47:42 +0200: Starting PostgREST 12.1...
03/Jun/2024:20:47:42 +0200: Listening on port 3000
03/Jun/2024:20:47:42 +0200: Attempting to connect to the database...
Assertion failed: *(&once->n) != 4 (threads.c: k5_once: 564)
[1]    1427036 IOT instruction (core dumped)  PGRST_DB_LOG_LEVEL=info PGRST_DB_URI= PGRST_DB_ANON_ROLE=postgres

This should allow bisecting.

steve-chavez · 2024-06-03T18:51:27Z

Can reproduce with the downloaded binary and a local PG (non nix tooled)

Same for me, it doesn't happen when using the nix postgrest-with-postgresql-* pg, only when using my distro postgres. What's strange is that it doesn't even log the database version, it just dies.

steve-chavez · 2024-06-03T18:58:49Z

Error comes from kerberos lib: https://github.com/krb5/krb5//blob/5f0023d5f05e95021a7caa1193f76f86871222ce/src/util/support/threads.c#L558-L565

Maybe the error starts from #3169? (GSSAPI)

wolfgangwalther · 2024-06-03T19:12:52Z

Interesting: The error doesn't seem to happen every time. It fails sometimes and sometimes doesn't - on the same commit.

wolfgangwalther · 2024-06-03T19:29:06Z

git bisect points to 3cf5656 as the first bad commit.

steve-chavez · 2024-06-03T19:59:56Z

Ah damn, it likely is the exception throwing and catching I did

postgrest/src/PostgREST/Listener.hs

Lines 45 to 53 in a46bea1

    
           tryRethrow :: IO () -> IO () 
        
           tryRethrow action =  do 
        
             act <- try action 
        
             whenLeft act (\ex -> do 
        
               AppState.putIsListenerOn appState False 
        
               observer $ DBListenFail dbChannel (Right $ Left ex) 
        
               unless configDbPoolAutomaticRecovery $ do 
        
                 killThread mainThreadId 
        
               throw ex)

Somehow it must be affecting some state on the C lib. I will try a different approach.

Why this doesn't happen on the local nix postgres though? Because it connects through unix sockets?

laurenceisla · 2024-06-03T20:43:30Z

Why this doesn't happen on the local nix postgres though? Because it connects through unix sockets?

I don't think so. Using postgrest-run in the nix environment but connecting to my local database over TCP works OK (it's my last example).

wolfgangwalther · 2024-06-03T21:24:12Z

I think it needs the combination of static executable + TCP to break.

steve-chavez · 2024-06-04T00:16:00Z

So it wasn't the exception catching/throwing, I just removed that and it fails the same.

Another change on 3cf5656 is that now the listener and the connection worker start in parallel.

Before the listener waited for the connection worker, here 3cf5656#diff-f6074642dc32a94e9e1997b21b0df631b2d3f098e0a81673edc22b89a86f49edL534-L538. But that was only done to reuse the exponential backoff retrying from the connection worker, I didn't know it would have this effect. I guess the kerberos lib doesn't work with parallel connections?

wolfgangwalther · 2024-06-04T13:06:12Z

Hm, not sure whether this is about kerberos (but yes, could be). Could also be about libpq itself:

https://www.postgresql.org/docs/current/libpq-threading.html

One thread restriction is that no two threads attempt to manipulate the same PGconn object at the same time. In particular, you cannot issue concurrent commands from different threads through the same connection object.

Maybe something like that is happening accidentally?

wolfgangwalther · 2024-06-04T13:06:49Z

Oh, on the same page later on:

If you are using Kerberos inside your application (in addition to inside libpq), you will need to do locking around Kerberos calls because Kerberos functions are not thread-safe. See function PQregisterThreadLock in the libpq source code for a way to do cooperative locking between libpq and your application.

Ah, that doesn't seem relevant, though, because we are not using kerberos additionally. But it could explain why libpq throws up in that area when maybe the thing from above happens?

Clears the limitation mentioned on PostgREST#3536 The Listener no longer uses the https://hackage.haskell.org/package/retry package and instead uses a much simpler IORef in AppState for the delays. Additionally it no longer uses exception throwing/catching, which is rather messy and brings some concerns(PostgREST#3569 (comment)).

Clears the limitation mentioned on #3536 The Listener no longer uses the https://hackage.haskell.org/package/retry package and instead uses a much simpler IORef in AppState for the delays. Additionally it no longer uses exception throwing/catching, which is rather messy and brings some concerns(#3569 (comment)).

wolfgangwalther · 2024-06-05T17:50:51Z

I tested the current main branch with disabled gssapi / krb5. This makes the error go away, too.

The question is whether we can find a way / configuration where we can have your changes and gssapi-support?

wolfgangwalther · 2024-06-05T18:00:36Z

For now, I pushed a revert of the GSSAPI commit. I will try this again, once we get a truly static libpq build via pkgsStatic - this could be related.

steve-chavez · 2024-06-05T18:05:48Z

Oh wait.. I have a fix ready now that brings back waiting between the listener and connection worker..

wolfgangwalther · 2024-06-05T18:12:13Z

Happy to have that in, if it improves the code. But I would still not want to release the GSSAPI change right now. I'm not 100% convinced that this can not cause problems elsewhere, maybe when two pool connections start up at the same time or something like that.

I actually kind of like the fact that we have a reproducer for this case, so I'm fine with keeping it as is.

Brings back the the signaling/waiting between the connection pool and the Listener. Prevents the GSSAPI error shown on PostgREST#3569

steve-chavez · 2024-06-05T18:44:42Z

Yeah, I think it's worth adding it back. If anything it reduces wastefully retrying both listener and the connection worker when postgres is completely down. Doing it on #3573.

maybe when two pool connections start up at the same time or something like that.

Right, that could still be trouble.

Brings back the the signaling/waiting between the connection pool and the Listener. Prevents the GSSAPI error shown on #3569

laurenceisla added the bug label Jun 3, 2024

vhpx mentioned this issue Jun 4, 2024

PostgREST 12.1 frequently stuck in "Attempting to connect to the database..." (Local Development) supabase/cli#2361

Closed

steve-chavez mentioned this issue Jun 5, 2024

correct exponential backoff on Listener #3572

Merged

wolfgangwalther closed this as completed Jun 5, 2024

steve-chavez added a commit to steve-chavez/postgrest that referenced this issue Jun 5, 2024

prevent GSSAPI error between Listener and pool

0568982

Brings back the the signaling/waiting between the connection pool and the Listener. Prevents the GSSAPI error shown on PostgREST#3569

steve-chavez mentioned this issue Jun 5, 2024

prevent GSSAPI error between Listener and pool #3573

Merged

steve-chavez added a commit that referenced this issue Jun 5, 2024

prevent GSSAPI error between Listener and pool

4beac10

Brings back the the signaling/waiting between the connection pool and the Listener. Prevents the GSSAPI error shown on #3569

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

"threads.c" error when running binaries or docker image for amd64 devel version #3569

"threads.c" error when running binaries or docker image for amd64 devel version #3569

laurenceisla commented Jun 3, 2024 •

edited by steve-chavez

Loading

steve-chavez commented Jun 3, 2024 •

edited

Loading

wolfgangwalther commented Jun 3, 2024 •

edited

Loading

wolfgangwalther commented Jun 3, 2024

steve-chavez commented Jun 3, 2024 •

edited

Loading

steve-chavez commented Jun 3, 2024 •

edited

Loading

wolfgangwalther commented Jun 3, 2024

wolfgangwalther commented Jun 3, 2024

steve-chavez commented Jun 3, 2024

laurenceisla commented Jun 3, 2024

wolfgangwalther commented Jun 3, 2024

steve-chavez commented Jun 4, 2024 •

edited

Loading

wolfgangwalther commented Jun 4, 2024

wolfgangwalther commented Jun 4, 2024 •

edited

Loading

wolfgangwalther commented Jun 5, 2024

wolfgangwalther commented Jun 5, 2024

steve-chavez commented Jun 5, 2024 •

edited

Loading

wolfgangwalther commented Jun 5, 2024

steve-chavez commented Jun 5, 2024

"threads.c" error when running binaries or docker image for amd64 devel version #3569

"threads.c" error when running binaries or docker image for amd64 devel version #3569

Comments

laurenceisla commented Jun 3, 2024 • edited by steve-chavez Loading

Environment

Description of issue

steve-chavez commented Jun 3, 2024 • edited Loading

wolfgangwalther commented Jun 3, 2024 • edited Loading

wolfgangwalther commented Jun 3, 2024

steve-chavez commented Jun 3, 2024 • edited Loading

steve-chavez commented Jun 3, 2024 • edited Loading

wolfgangwalther commented Jun 3, 2024

wolfgangwalther commented Jun 3, 2024

steve-chavez commented Jun 3, 2024

laurenceisla commented Jun 3, 2024

wolfgangwalther commented Jun 3, 2024

steve-chavez commented Jun 4, 2024 • edited Loading

wolfgangwalther commented Jun 4, 2024

wolfgangwalther commented Jun 4, 2024 • edited Loading

wolfgangwalther commented Jun 5, 2024

wolfgangwalther commented Jun 5, 2024

steve-chavez commented Jun 5, 2024 • edited Loading

wolfgangwalther commented Jun 5, 2024

steve-chavez commented Jun 5, 2024

laurenceisla commented Jun 3, 2024 •

edited by steve-chavez

Loading

steve-chavez commented Jun 3, 2024 •

edited

Loading

wolfgangwalther commented Jun 3, 2024 •

edited

Loading

steve-chavez commented Jun 3, 2024 •

edited

Loading

steve-chavez commented Jun 3, 2024 •

edited

Loading

steve-chavez commented Jun 4, 2024 •

edited

Loading

wolfgangwalther commented Jun 4, 2024 •

edited

Loading

steve-chavez commented Jun 5, 2024 •

edited

Loading