Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

macOs Big Sur: ERROR: checkpoint request failed #140

Open
GreteM2nd opened this issue Dec 7, 2020 · 40 comments
Open

macOs Big Sur: ERROR: checkpoint request failed #140

GreteM2nd opened this issue Dec 7, 2020 · 40 comments
Labels
status: on-hold We can't start working on this issue yet

Comments

@GreteM2nd
Copy link

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
Copy link

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
Copy link
Collaborator

tomix26 commented Dec 8, 2020

@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
Copy link
Collaborator

tomix26 commented Dec 8, 2020

@GreteM2nd Also make sure you have enough disk space.

@tomix26
Copy link
Collaborator

tomix26 commented Dec 8, 2020

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

@tomix26 tomix26 added the status: waiting-for-feedback We need additional information before we can continue label Dec 8, 2020
@dirkbolte
Copy link

@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
Copy link
Author

GreteM2nd commented Dec 9, 2020

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?
image

@tomix26
Copy link
Collaborator

tomix26 commented Dec 11, 2020

@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
Copy link

@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
Copy link

andywhite27 commented Dec 16, 2020

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
Copy link
Collaborator

tomix26 commented Dec 16, 2020

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
Copy link

Hi @tomix26, I have emailed you the details.

@wilddog1979
Copy link

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
Copy link

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

@ejl888
Copy link

ejl888 commented Dec 21, 2020

I got the same error. Below an extract from the log when starting my IT.
This is after upgrading to MacOS Big Sur 11.1 (I skipped 11.0.1)
First 2 test's fail and then tests start working again.

First run after deleting the embedded-pg folder

2020-12-21 13:47:16.048  INFO [,,,] [] 27597 --- [  prefetching-3] o.f.core.internal.command.DbMigrate      : Successfully applied 70 migrations to schema "public" (execution time 00:00.834s)
2020-12-21 13:47:16.445  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.445 CET [27610] PANIC:  could not open file "pg_xact": Interrupted system call
2020-12-21 13:47:16.446  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.445 CET [27608] LOG:  checkpointer process (PID 27610) was terminated by signal 6: Abort trap
2020-12-21 13:47:16.446  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.445 CET [27608] LOG:  terminating any other active server processes
2020-12-21 13:47:16.446  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.445 CET [27624] WARNING:  terminating connection because of crash of another server process
2020-12-21 13:47:16.446  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.445 CET [27624] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2020-12-21 13:47:16.446  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.445 CET [27624] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2020-12-21 13:47:16.446  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.446 CET [27623] WARNING:  terminating connection because of crash of another server process
2020-12-21 13:47:16.446  INFO [,,,] [] 27597 --- [gres:pid(27608)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 13:47:16.446 CET [27623] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.

second run after deleting folder

2020-12-21 14:04:54.390  INFO [,,,] [] 27899 --- [  prefetching-1] o.f.core.internal.command.DbMigrate      : Successfully applied 70 migrations to schema "public" (execution time 00:00.547s)
2020-12-21 14:04:54.399  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.399 CET [27916] ERROR:  could not access status of transaction 0
2020-12-21 14:04:54.400  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.399 CET [27916] DETAIL:  Could not open file "pg_xact/0000": Interrupted system call.
2020-12-21 14:04:54.500  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27930] ERROR:  checkpoint request failed
2020-12-21 14:04:54.500  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27930] HINT:  Consult recent messages in the server log for details.
2020-12-21 14:04:54.500  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27930] STATEMENT:  CREATE DATABASE cvjrsfilwiwe TEMPLATE palqhrkrugzf OWNER postgres ENCODING 'utf8'
2020-12-21 14:04:54.500  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27929] ERROR:  checkpoint request failed
2020-12-21 14:04:54.500  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27929] HINT:  Consult recent messages in the server log for details.
2020-12-21 14:04:54.500  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27929] STATEMENT:  CREATE DATABASE vdqeczgddatw TEMPLATE palqhrkrugzf OWNER postgres ENCODING 'utf8'
2020-12-21 14:04:54.501  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27928] ERROR:  checkpoint request failed
2020-12-21 14:04:54.501  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27928] HINT:  Consult recent messages in the server log for details.
2020-12-21 14:04:54.501  INFO [,,,] [] 27899 --- [gres:pid(27914)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2020-12-21 14:04:54.500 CET [27928] STATEMENT:  CREATE DATABASE jfigctvzzkjd TEMPLATE palqhrkrugzf OWNER postgres ENCODING 'utf8'
2020-12-21 14:04:54.512 ERROR [,,,] [] 27899 --- [           main] wayEmbeddedPostgresDataSourceFactoryBean : Unexpected error during the initialization of embedded database

java.util.concurrent.CompletionException: org.postgresql.util.PSQLException: ERROR: checkpoint request failed
  Hint: Consult recent messages in the server log for details.
	at io.zonky.test.db.flyway.DefaultFlywayDataSourceContext.lambda$reload$0(DefaultFlywayDataSourceContext.java:114)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642)
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478)
	at java.base/java.util.concurrent.CompletableFuture.uniApplyNow(CompletableFuture.java:677)
	at java.base/java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:658)
	at java.base/java.util.concurrent.CompletableFuture.thenApplyAsync(CompletableFuture.java:2104)
	at io.zonky.test.db.flyway.DefaultFlywayDataSourceContext.reload(DefaultFlywayDataSourceContext.java:107)
	at io.zonky.test.db.postgres.FlywayEmbeddedPostgresDataSourceFactoryBean.postProcessBeforeInitialization(FlywayEmbeddedPostgresDataSourceFactoryBean.java:89)

I can confirm that it works by adding the following dependency to the pom.

        <dependency>
            <groupId>io.zonky.test.postgres</groupId>
            <artifactId>embedded-postgres-binaries-darwin-amd64</artifactId>
            <version>12.1.0-1</version>
        </dependency>

@tomix26
Copy link
Collaborator

tomix26 commented Dec 30, 2020

Hi @andywhite27, yes I got it, thank you very much. And thank you all for the provided details.

The zipped postgres directory you sent is identical to my directory, so the binaries are not corrupted and the problem will probably be somewhere else. I also checked the logfile and it seems that all the errors are similar, however, the problem occurs when accessing different files.

PANIC:  could not open file "pg_logical/replorigin_checkpoint.tmp": Interrupted system call

PANIC:  could not open file "pg_xact": Interrupted system call

DETAIL:  Could not open file "pg_xact/0000": Interrupted system call.

So I guess the root cause is the Interrupted system call error. When I googled the possible causes, I found the following issue https://forum.eset.com/topic/26346-issue-with-git-push-failing-on-macos-110-big-sur-with-eset-cyber-security-pro-for-mac. Which could explain why for most people it works without any issues, and the problem only occurs rarely on some macs.

So, are you using Eset or any other antivirus service? If so, please try to temporarily disable the service to see if the tests will be passing or not. If not, I will send further instructions to investigate the problem.

@dirkbolte
Copy link

I have an antivirus software installed which also offers real-time file system protection (bitdefender in my case). While isolating the error I also turned it off to eradicate side effects but maybe I missed something. Will try it again.

@GreteM2nd
Copy link
Author

I also have Eset and when real-time file system protection is disabled then the problem doesn't seem to appear - as soon as it's enabled then the issue occurs again.

@andywhite27
Copy link

I have AVG. With 'File Shield' on it consistently fails with it off it consistently works!

Thanks very much for your investigation and insight @tomix26!

@xCoBaLTz
Copy link

I am experiencing the same issue, but even with my 'Realtime Shield' off I continue to get the following error.

Caused by: org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'testDbConfiguration': Unsatisfied dependency expressed through field 'dataSource'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'localDataSource': FactoryBean threw exception on object creation; nested exception is org.postgresql.util.PSQLException: ERROR: checkpoint request failed

@tomix26
Copy link
Collaborator

tomix26 commented Jan 18, 2021

Maybe your antivirus performs some type of scan even after turning off the realtime shield. I'm just guessing, I can't verify, I couldn't reproduce the problem.

Is there anyone who doesn't use antivirus at all and is facing with the same issues?

@xCoBaLTz
Copy link

Thank you for trying, I actually got it to build by just uninstalling my antivirus completely. 👍🏽

@dc-up42
Copy link

dc-up42 commented Jan 18, 2021

Have tried turning the real-time file protection off - still the same problem.

In the logs I have the following:

2021-01-18 16:50:37.907  INFO 3939 --- [  prefetching-2] o.f.core.internal.command.DbMigrate      : Successfully applied 119 migrations to schema "public" (execution time 00:01.066s)
2021-01-18 16:50:37.920  INFO 3939 --- [tgres:pid(3967)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 16:50:37.920 CET [3969] ERROR:  could not open directory "pg_logical/mappings": Interrupted system call
2021-01-18 16:50:38.019  INFO 3939 --- [tgres:pid(3967)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 16:50:38.019 CET [3981] ERROR:  checkpoint request failed
2021-01-18 16:50:38.019  INFO 3939 --- [tgres:pid(3967)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 16:50:38.019 CET [3981] HINT:  Consult recent messages in the server log for details.
2021-01-18 16:50:38.019  INFO 3939 --- [tgres:pid(3967)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 16:50:38.019 CET [3981] STATEMENT:  CREATE DATABASE acmrrszlwvqf TEMPLATE pbdbledbdths OWNER postgres ENCODING 'utf8'
2021-01-18 16:50:38.071 ERROR 3939 --- [    Test worker] wayEmbeddedPostgresDataSourceFactoryBean : Unexpected error during the initialization of embedded database

I've also seen Could not open file "pg_xact/0000": Interrupted system call. and other files failing to be open.

@dc-up42
Copy link

dc-up42 commented Jan 18, 2021

I tried putting a breakpoint after the migrations had been applied: managed to actually connect to the database using a client, saw all the migrations actually applied. Haven't tried any updates/inserts though.

BTW, I had had dyld: Library not loaded: @loader_path/../lib/libpq.5.dylib before - "fixed" by something along the lines of brew install posgres, brew reinstall libpq. Not sure here - the experiment was not clean. I suspect that I could have some problems with the dynamic libraries, with which some PG executable is linked 🤦

@tomix26
Copy link
Collaborator

tomix26 commented Jan 18, 2021

@xCoBaLTz Thank you very much for the information 👍

@dc-up42 Please try the latest versions of postgres binaries mentioned here: zonkyio/embedded-postgres-binaries#21 (comment)

@dc-up42
Copy link

dc-up42 commented Jan 18, 2021

@dc-up42 Please try the latest versions of postgres binaries mentioned here: zonkyio/embedded-postgres-binaries#21 (comment)

@tomix26 Sadly, doesn't work. Tried several different versions between 10 and 13 with the suffix -1.

UPDATE:

Got some log messages I haven't seen before, while running the test several times without cleaning the $TMPDIR:

logs
2021-01-18 17:41:34.733  INFO 8257 --- [  prefetching-1] o.f.core.internal.command.DbMigrate      : Successfully applied 119 migrations to schema "public" (execution time 00:00.964s)
2021-01-18 17:41:35.068  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.067 CET [8273] PANIC:  could not open file "pg_xact": Interrupted system call
2021-01-18 17:41:35.068  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8271] LOG:  checkpointer process (PID 8273) was terminated by signal 6: Abort trap
2021-01-18 17:41:35.068  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8271] LOG:  terminating any other active server processes
2021-01-18 17:41:35.068  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8287] WARNING:  terminating connection because of crash of another server process
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8287] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8287] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8286] WARNING:  terminating connection because of crash of another server process
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8286] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8286] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8285] WARNING:  terminating connection because of crash of another server process
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8285] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8285] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8276] WARNING:  terminating connection because of crash of another server process
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8276] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2021-01-18 17:41:35.069  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.068 CET [8276] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2021-01-18 17:41:35.070  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.070 CET [8271] LOG:  all server processes terminated; reinitializing
2021-01-18 17:41:35.087  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.087 CET [8288] LOG:  database system was interrupted; last known up at 2021-01-18 17:41:34 CET
2021-01-18 17:41:35.090  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.090 CET [8289] FATAL:  the database system is in recovery mode
2021-01-18 17:41:35.092  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.092 CET [8288] LOG:  database system was not properly shut down; automatic recovery in progress
2021-01-18 17:41:35.097  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.097 CET [8288] LOG:  redo starts at 0/1818BE8
2021-01-18 17:41:35.098  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.097 CET [8288] LOG:  invalid record length at 0/1818C98: wanted 24, got 0
2021-01-18 17:41:35.098  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.097 CET [8288] LOG:  redo done at 0/1818C28
2021-01-18 17:41:35.109  INFO 8257 --- [tgres:pid(8271)] i.z.t.d.p.embedded.EmbeddedPostgres      : 2021-01-18 17:41:35.108 CET [8290] FATAL:  the database system is in recovery mode
2021-01-18 17:41:35.110 ERROR 8257 --- [    Test worker] wayEmbeddedPostgresDataSourceFactoryBean : Unexpected error during the initialization of embedded database

java.util.concurrent.CompletionException: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
	at io.zonky.test.db.flyway.DefaultFlywayDataSourceContext.lambda$reload$0(DefaultFlywayDataSourceContext.java:114)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642)
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478)
	at java.base/java.util.concurrent.CompletableFuture.uniApplyNow(CompletableFuture.java:677)
	at java.base/java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:658)
	at java.base/java.util.concurrent.CompletableFuture.thenApplyAsync(CompletableFuture.java:2104)
	at io.zonky.test.db.flyway.DefaultFlywayDataSourceContext.reload(DefaultFlywayDataSourceContext.java:107)
	at io.zonky.test.db.postgres.FlywayEmbeddedPostgresDataSourceFactoryBean.postProcessBeforeInitialization(FlywayEmbeddedPostgresDataSourceFactoryBean.java:89)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:415)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1786)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:594)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:516)
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:324)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:322)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202)
	at org.springframework.beans.factory.config.DependencyDescriptor.resolveCandidate(DependencyDescriptor.java:276)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:1307)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:1227)
	at org.springframework.beans.factory.support.ConstructorResolver.resolveAutowiredArgument(ConstructorResolver.java:884)
	at org.springframework.beans.factory.support.ConstructorResolver.createArgumentArray(ConstructorResolver.java:788)
	at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:538)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1336)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1176)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:556)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:516)
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:324)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:322)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:311)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202)
	at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1109)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:869)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:551)
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:143)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:758)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:750)
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:397)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:315)
	at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:120)
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:99)
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:124)
	at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:123)
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.postProcessFields(MockitoTestExecutionListener.java:95)
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.injectFields(MockitoTestExecutionListener.java:79)
	at org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener.prepareTestInstance(MockitoTestExecutionListener.java:54)
	at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:244)
	at org.springframework.test.context.junit.jupiter.SpringExtension.postProcessTestInstance(SpringExtension.java:98)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeTestInstancePostProcessors$5(ClassBasedTestDescriptor.java:341)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.executeAndMaskThrowable(ClassBasedTestDescriptor.java:346)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeTestInstancePostProcessors$6(ClassBasedTestDescriptor.java:341)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
	at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
	at java.base/java.util.stream.StreamSpliterators$WrappingSpliterator.forEachRemaining(StreamSpliterators.java:312)
	at java.base/java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:735)
	at java.base/java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:734)
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeTestInstancePostProcessors(ClassBasedTestDescriptor.java:340)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.instantiateAndPostProcessTestInstance(ClassBasedTestDescriptor.java:263)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$testInstancesProvider$2(ClassBasedTestDescriptor.java:256)
	at java.base/java.util.Optional.orElseGet(Optional.java:369)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$testInstancesProvider$3(ClassBasedTestDescriptor.java:255)
	at org.junit.jupiter.engine.execution.TestInstancesProvider.getTestInstances(TestInstancesProvider.java:29)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$prepare$0(TestMethodTestDescriptor.java:108)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.prepare(TestMethodTestDescriptor.java:107)
	at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.prepare(TestMethodTestDescriptor.java:71)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$prepare$1(NodeTestTask.java:107)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.prepare(NodeTestTask.java:107)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:75)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:248)
	at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$5(DefaultLauncher.java:211)
	at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:226)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:199)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:132)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.processAllTestClasses(JUnitPlatformTestClassProcessor.java:99)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor$CollectAllTestClassesExecutor.access$000(JUnitPlatformTestClassProcessor.java:79)
	at org.gradle.api.internal.tasks.testing.junitplatform.JUnitPlatformTestClassProcessor.stop(JUnitPlatformTestClassProcessor.java:75)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.stop(SuiteTestClassProcessor.java:61)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
	at com.sun.proxy.$Proxy5.stop(Unknown Source)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.stop(TestWorker.java:133)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:182)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:164)
	at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:414)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:56)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:350)
	at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:473)
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:393)
	at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
	at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:153)
	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:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	... 1 common frames omitted
Caused by: java.io.EOFException: null
	at org.postgresql.core.PGStream.receiveChar(PGStream.java:443)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2057)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
	... 13 common frames omitted

@tomix26
Copy link
Collaborator

tomix26 commented Jan 20, 2021

@dc-up42 The error in the attached log file is the same one that is reported in this issue. So please try to temporarily uninstall the antivirus from your computer. Because for some reporters, turning off real-time protection was not enough, but a complete uninstall has always solved the problem.

@dc-up42
Copy link

dc-up42 commented Jan 22, 2021

@tomix26 Thanks for responding here. On the corp laptop I'm not allowed to do that :(
Will have to work something out 🤷‍♂️

@tomix26
Copy link
Collaborator

tomix26 commented Feb 9, 2021

Sure, that's understandable. As a last resort, you can try to change the destination of the database data from the temp directory (java.io.tmpdir) to another directory. Maybe the antivirus will calm it down.

This should be possible to change using system property: ot.epg.working-dir=/home/xxx/embedded-pg

@tomix26 tomix26 added status: on-hold We can't start working on this issue yet and removed status: waiting-for-feedback We need additional information before we can continue labels Feb 9, 2021
@ilyaxvgreat
Copy link

Sure, that's understandable. As a last resort, you can try to change the destination of the database data from the temp directory (java.io.tmpdir) to another directory. Maybe the antivirus will calm it down.

This should be possible to change using system property: ot.epg.working-dir=/home/xxx/embedded-pg

I have to add this row in application properties in my project ?

@tomix26
Copy link
Collaborator

tomix26 commented Feb 18, 2021

No, it's a system property, so it needs to be passed at the start of the java process. If you are using Maven, you can set it in the configuration of Surefire or Failsafe plugin. Detailed instructions are here: https://maven.apache.org/surefire/maven-surefire-plugin/examples/system-properties.html.

@ilyaxvgreat
Copy link

Нет, это системное свойство, поэтому его необходимо передать в начале java-процесса. Если вы используете Maven, вы можете установить его в конфигурации плагина Surefire или Failsafe. Подробные инструкции находятся здесь: https://maven.apache.org/surefire/maven-surefire-plugin/examples/system-properties.html .

and what about gradle ? what would be the best practice ?

@tomix26
Copy link
Collaborator

tomix26 commented Feb 18, 2021

In my opinion, the best practice is to use Google ...

@wilddog1979
Copy link

Нет, это системное свойство, поэтому его необходимо передать в начале java-процесса. Если вы используете Maven, вы можете установить его в конфигурации плагина Surefire или Failsafe. Подробные инструкции находятся здесь: https://maven.apache.org/surefire/maven-surefire-plugin/examples/system-properties.html .

and what about gradle ? what would be the best practice ?

create or locate gradle.properties file in your project folder. Add this line.

systemProp.ot.epg.working-dir=/home/xxx/embedded-pg

Note that, I did not test this suggestion yet. You can find more description about gradle.properties here: https://docs.gradle.org/current/userguide/build_environment.html

@ilyaxvgreat
Copy link

ilyaxvgreat commented Feb 19, 2021

I added
@AutoConfigureEmbeddedDatabase(provider = DOCKER)

and app.prop and dependency following with your documentation and all work well.

But it is a temporary solution. Will be waiting for updates

@ilyaxvgreat
Copy link

Нет, это системное свойство, поэтому его необходимо передать в начале java-процесса. Если вы используете Maven, вы можете установить его в конфигурации плагина Surefire или Failsafe. Подробные инструкции находятся здесь: https://maven.apache.org/surefire/maven-surefire-plugin/examples/system-properties.html .

and what about gradle ? what would be the best practice ?

create or locate gradle.properties file in your project folder. Add this line.

systemProp.ot.epg.working-dir=/home/xxx/embedded-pg

Note that, I did not test this suggestion yet. You can find more description about gradle.properties here: https://docs.gradle.org/current/userguide/build_environment.html

do you have any results?

@bfrggit
Copy link

bfrggit commented Mar 24, 2021

Unfortunately this happens on me also. macOS 11.2.3. Setting LC_ env variables does not help - either if they are set in .zshrc or build.gradle. Cannot disable/uninstall system protection to test due to company security policies.

Error was:

DETAIL:  Could not open file "pg_xact/0000": Interrupted system call.

I cannot help with testing this though, since we decided to move on with Testcontainers to avoid similar issues in the future.

@tomix26
Copy link
Collaborator

tomix26 commented Mar 26, 2021

@bfrggit If you want, you can also use this library together with Testcontainers using Docker provider. Note that since version 2.0.0 this will be the default settings.

@wilddog1979
Copy link

Here is my tested and working solution:

  1. Make sure you have Docker installed and it was started
  2. Make sure you have org.testcontainers:postgresql added to the dependencies. I have the following dependencies in my gradle.build file.
    testImplementation 'io.zonky.test:embedded-database-spring-test:1.6.3'
    testImplementation 'org.testcontainers:postgresql:1.15.1'
  1. You can do few things on your local
    a. Add this to your command line while you are running your tests: -Dzonky.test.database.provider=DOCKER
    b. You can add this to your ~/.gradle/gradle.properties or gradle.properties of your project: systemProp.zonky.test.database.provider=DOCKER

This is going to fix test running with embedded Postgres on your local. This will not impact your CI process because it will continue to use the default settings. Of course you have to take care of those settings if you have similar problems in that environment but definitely this will solve the problems transparently on your local development environment.

@bfrggit
Copy link

bfrggit commented Apr 12, 2021

@wilddog1979 Thanks for the info.

My understanding is that this may impact your CI if your runner does not have Docker.

For us, before seeing this workaround, we changed to use testcontainers directly. We noted that by using this proj we can probably avoid some setups needed to configure application properties for the container but this also means that we are adding one more dependency.

@IvanGTrendafilov
Copy link

I faced with the same issue after updating to MacOS Big Sur. I am using io.zonky.test:embedded-postgres to start Postgre before execution of integration tests and after updating from 1.2.6 to 1.3.0 I can confirm that everything working fine.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: on-hold We can't start working on this issue yet
Projects
None yet
Development

No branches or pull requests