macOs Big Sur: ERROR: checkpoint request failed

[GreteM2nd]

Getting Failed to load ApplicationContext when running multiple tests together after macOS update to Big Sur. When running just one test then everything usually works the first time after restarting the computer, but later the error starts to occur even with running just one test.

Caused by: org.postgresql.util.PSQLException: ERROR: checkpoint request failed at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2532) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2267) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:312) at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:448) at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:369) at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:153) at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:142) at io.zonky.test.db.provider.impl.ZonkyPostgresDatabaseProvider$DatabaseInstance$DatabaseTemplate.executeStatement(ZonkyPostgresDatabaseProvider.java:163) at io.zonky.test.db.provider.impl.ZonkyPostgresDatabaseProvider$DatabaseInstance$DatabaseTemplate.createDatabase(ZonkyPostgresDatabaseProvider.java:156) at io.zonky.test.db.provider.impl.ZonkyPostgresDatabaseProvider.getDatabase(ZonkyPostgresDatabaseProvider.java:94) at io.zonky.test.db.provider.impl.PrefetchingDatabaseProvider$PrefetchingTask.lambda$new$0(PrefetchingDatabaseProvider.java:252) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.zonky.test.db.provider.impl.PrefetchingDatabaseProvider$PrefetchingTask.run(PrefetchingDatabaseProvider.java:259) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ... 1 more

Updated to 1.6.1 to resolve a different issue on Big Sur, but this one still remains.

[dirkbolte]

Hit the same error on Big Sur. It looks like the wait for datasource isn't working: I had one setup with ~7 tests of which the first 3 where failing. Depending on timing, sometimes all worked, sometimes not.

I created a git repo with a minimal setup for reproduction: https://github.com/dirkbolte/flyway_zonky

[tomix26]

@dirkbolte Thank you very much for the reproducer. I tried it and I'm really getting an error, but it's different from the one mentioned in this report. It fails with dyld: Library not loaded: @loader_path/../lib/libpq.5.dylib, which is described in #132. After upgrade to io.zonky.test.postgres:embedded-postgres-binaries-darwin-amd64:12.1.0-1, it started working again. I ran the SampleRepositoryTest test class 100 times (700 tests in total) and all tests passed. Tested on macOS Big Sur.

@GreteM2nd I guess that the error could probably be specific to your system. The CREATE DATABASE %s TEMPLATE %s OWNER %s ENCODING 'utf8' sql statement is executed when the error occurs. And I don't see any relation to the checkpoints here. So please try to clean up the /tmp/embedded-pg/PG-XYZ directory containing temporary binaries of the embedded database, restart your system, and so on. Maybe that will help.

[tomix26]

@GreteM2nd Also make sure you have enough disk space.

[tomix26]

There is a similar issue, but without a solution: https://www.postgresql.org/message-id/f916d72a0605291223v3a5e1b9bwa57cc9eac96202a0%40mail.gmail.com

[dirkbolte]

@tomix26 thanks for the hint - the upgrade got me further as it showed additional log messages but didn't fix it for me yet. I now ended up with 13.1.

09:28:46.132 [prefetching-3] DEBUG org.flywaydb.core.internal.sqlscript.DefaultSqlScriptExecutor - Update Count: 0
09:28:46.132 [prefetching-3] DEBUG org.flywaydb.core.internal.command.DbMigrate - Successfully completed migration of schema "public" to version "1 - sample initialization"
09:28:46.135 [prefetching-3] DEBUG org.flywaydb.core.internal.schemahistory.JdbcTableSchemaHistory - Schema History table "public"."flyway_schema_history" successfully updated to reflect changes
09:28:46.139 [prefetching-3] INFO org.flywaydb.core.internal.command.DbMigrate - Successfully applied 1 migration to schema "public" (execution time 00:00.018s)
09:28:46.140 [prefetching-3] DEBUG org.flywaydb.core.Flyway - Memory usage: 26 of 512M
09:28:46.148 [postgres:pid(18579)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-09 09:28:46.148 CET [18581] ERROR:  could not access status of transaction 0
09:28:46.148 [postgres:pid(18579)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-09 09:28:46.148 CET [18581] DETAIL:  Could not open file "pg_xact/0000": Interrupted system call.
09:28:46.148 [postgres:pid(18579)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-09 09:28:46.148 CET [18592] ERROR:  checkpoint request failed
09:28:46.148 [postgres:pid(18579)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-09 09:28:46.148 CET [18592] HINT:  Consult recent messages in the server log for details.
09:28:46.148 [postgres:pid(18579)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-09 09:28:46.148 CET [18592] STATEMENT:  CREATE DATABASE vexahuoejeru TEMPLATE ysmsoxtldczg OWNER postgres ENCODING 'utf8'
09:28:46.163 [main] ERROR io.zonky.test.db.postgres.FlywayEmbeddedPostgresDataSourceFactoryBean - Unexpected error during the initialization of embedded database
java.util.concurrent.CompletionException: org.postgresql.util.PSQLException: ERROR: checkpoint request failed

[GreteM2nd]

Clearing the /tmp/embedded-pg/PG-XYZ directory is something I have tried before, it seems to be a temporary fix. At the moment I have to clear it every time before running tests and then everything works fine. But running tests again without clearing the directory results in the same error as before. Also in the past, this has stopped helping sometimes.

I didn't have io.zonky.test.postgres:embedded-postgres-binaries-darwin-amd64 added as a separate dependency before (just io.zonky.test:embedded-database-spring-test and before the Big Sur update it worked fine without it). I tried adding it separately, but it didn't make anything better at the moment.

@tomix26 you mentioned earlier that some things were fixed with upgrading io.zonky.test.postgres:embedded-postgres-binaries-darwin-amd64 to 12.1.0-1. I did notice that currently the version that comes with io.zonky.test:embedded-database-spring-test:1.6.1 for the binaries for Darwin (and other platforms as well) is 10.11.0-1. Could this earlier version be causing problems with the temporary binaries in /tmp/embedded-pg/PG-XYZ?

[tomix26]

@dirkbolte The version 13.1 is not supported on macOS Big Sur at this moment, you have to use one of the latest supported versions (9.4.25-1, 9.5.20-1, 9.6.16-1, 10.11.0-1, 11.6.0-1, 12.1.0-1)

@GreteM2nd It isn't neccesary to add io.zonky.test.postgres:embedded-postgres-binaries-darwin-amd64 dependency explicitly, using the io.zonky.test:embedded-database-spring-test:1.6.1 should be enough. That was only a hint for @dirkbolte because he overrides the default version of postgres binaries with an unsupported one.

Ok, since I can't reproduce the problem, I will need the complete logs of your tests and also the content of your /tmp/embedded-pg/PG-XYZ directory. Without it, I am not able to investigate the problem further.

[dirkbolte]

@tomix26 I tried again with 12.1.0-1 and it still fails - is there anything beside the test logs I can provide? Unfortunately I cannot find any additional log files.

20:19:59.455 [postgres:pid(50577)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-12 20:19:59.455 CET [50579] ERROR:  could not access status of transaction 0
20:19:59.455 [postgres:pid(50577)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-12 20:19:59.455 CET [50579] DETAIL:  Could not open file "pg_xact/0000": Interrupted system call.
20:19:59.455 [postgres:pid(50577)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-12 20:19:59.455 CET [50590] ERROR:  checkpoint request failed
20:19:59.455 [postgres:pid(50577)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-12 20:19:59.455 CET [50590] HINT:  Consult recent messages in the server log for details.
20:19:59.456 [postgres:pid(50577)] INFO io.zonky.test.db.postgres.embedded.EmbeddedPostgres - 2020-12-12 20:19:59.455 CET [50590] STATEMENT:  CREATE DATABASE bdcptpvaykxa TEMPLATE pqmokonrzhqn OWNER postgres ENCODING 'utf8'
20:19:59.480 [Test worker] ERROR io.zonky.test.db.postgres.FlywayEmbeddedPostgresDataSourceFactoryBean - Unexpected error during the initialization of embedded database

Should I keep adding it to this issue or move it to a new issue?

[andywhite27]

This is an issue for me too. I'm happy to provide any details needed.

I'm using io.zonky.test:embedded-database-spring-test:1.6.1 and I've tried with and without io.zonky.test.postgres:embedded-postgres-binaries-darwin-amd64 and it makes no difference. Clearing embeddedpg doesn't help and neither did a reboot

[tomix26]

As I wrote, I need more information:

I will need the complete logs of your tests and also the content of your /tmp/embedded-pg/PG-XYZ directory

[andywhite27]

Hi @tomix26, I have emailed you the details.

[wilddog1979]

Let me give more details I found:

/var/folders/27/jtmnd5ms42x240t_0qdb7c1w0000gn/T/embedded-pg/PG-1125f7ce482c8c7f3a40d52e5753bcf5/bin/initdb --version
initdb (PostgreSQL) 10.11

I tailed the logfile and I found the followings. Note that Postgres is starting and cannot open pg_xact/0000 and goes into fixing the file after a time. Meanwhile tests are started and cannot connect to database and the first few test cases are failing with "ERROR: checkpoint request failed" message. Finally at the 3rd attempt pfycmsqjhjna database is created fine and you can see Liquibase is kicking in.

2020-12-17 09:18:40.009 CET [5095] LOG:  listening on IPv6 address "::1", port 51339
2020-12-17 09:18:40.009 CET [5095] LOG:  listening on IPv4 address "127.0.0.1", port 51339
2020-12-17 09:18:40.010 CET [5095] LOG:  listening on Unix socket "/tmp/.s.PGSQL.51339"
2020-12-17 09:18:40.023 CET [5096] LOG:  database system was shut down at 2020-12-17 09:18:39 CET
2020-12-17 09:18:40.029 CET [5095] LOG:  database system is ready to accept connections
2020-12-17 09:18:41.106 CET [5104] LOG:  incomplete startup packet
2020-12-17 09:18:41.645 CET [5097] ERROR:  could not access status of transaction 0
2020-12-17 09:18:41.645 CET [5097] DETAIL:  Could not open file "pg_xact/0000": Interrupted system call.
2020-12-17 09:18:41.746 CET [5110] ERROR:  checkpoint request failed
2020-12-17 09:18:41.746 CET [5110] HINT:  Consult recent messages in the server log for details.
2020-12-17 09:18:41.746 CET [5110] STATEMENT:  CREATE DATABASE vhzcyzthktoh TEMPLATE flqqvyoozxnk OWNER postgres ENCODING 'utf8'
2020-12-17 09:18:41.746 CET [5108] ERROR:  checkpoint request failed
2020-12-17 09:18:41.746 CET [5108] HINT:  Consult recent messages in the server log for details.
2020-12-17 09:18:41.746 CET [5108] STATEMENT:  CREATE DATABASE hjmatzscdsmx TEMPLATE flqqvyoozxnk OWNER postgres ENCODING 'utf8'
2020-12-17 09:18:42.649 CET [5109] ERROR:  checkpoint request failed
2020-12-17 09:18:42.649 CET [5109] HINT:  Consult recent messages in the server log for details.
2020-12-17 09:18:42.649 CET [5109] STATEMENT:  CREATE DATABASE pfycmsqjhjna TEMPLATE flqqvyoozxnk OWNER postgres ENCODING 'utf8'
2020-12-17 09:18:49.547 CET [5143] ERROR:  relation "public.databasechangeloglock" does not exist at character 22
2020-12-17 09:18:49.547 CET [5143] STATEMENT:  SELECT COUNT(*) FROM public.databasechangeloglock

[andywhite27]

Hi @tomix26, did you get my email last week with the details you requested? Is there anything I can do to help?