Failure to delete temp files when running in Spring Context

[zemudkram]

I have wired up a PostgresService to be used in our Spring context-based tests. It is Lifecycle aware (it implements Lifecycle) and is started through start() method and stopped through a stop method which calls

process.stop();

When the test completes and the context is shutting down, I get an IllegalStateException, and the temporary files created at startup are not deleted. It seems to occur when a shutdown hook is added to clean up the files:

2016-02-26 15:09:00,992 [Thread-6] INFO de.flapdoodle.embed.process.runtime.ProcessControl - execSuccess: true [kill, -2, 69506] 2016-02-26 15:09:01,157 [Thread-6] WARN de.flapdoodle.embed.process.io.file.Files - could not delete /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-4f4bcf51-7ba0-401d-8a1d-ecf5f55bb1ba/db-content-0ca454b3-56c3-4b75-88ba-d5ad911f7fd9. Will try to delete it again when program exits. 2016-02-26 15:09:01,159 [Thread-47] INFO com.anzcro.o3.util.db.PostgresService - STOPPED EMBEDDED POSTGRES 2016-02-26 15:09:01,159 [Thread-47] INFO org.springframework.beans.factory.support.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@26aa12dd: defining beans [propertyPlaceholderConfigurerBusinessBase,postgresService,...]; root of factory hierarchy Exception in thread "Thread-6" java.lang.IllegalStateException: Shutdown in progress at java.lang.ApplicationShutdownHooks.add(ApplicationShutdownHooks.java:66) at java.lang.Runtime.addShutdownHook(Runtime.java:211) at de.flapdoodle.embed.process.io.file.FileCleaner.forceDeleteOnExit(FileCleaner.java:52) at de.flapdoodle.embed.process.io.file.Files.forceDelete(Files.java:125) at ru.yandex.qatools.embed.postgresql.PostgresProcess.deleteTempFiles(PostgresProcess.java:157) at ru.yandex.qatools.embed.postgresql.PostgresProcess.stopInternal(PostgresProcess.java:117) at de.flapdoodle.embed.process.runtime.AbstractProcess.stop(AbstractProcess.java:170) at de.flapdoodle.embed.process.runtime.AbstractProcess$JobKiller.run(AbstractProcess.java:243) at java.lang.Thread.run(Thread.java:745)

It looks like it's failing to register the shutdown hook that deletes the files.

[smecsia]

@zemudkram This might be a bug in de.flapdoodle.embed.process.
We could catch any exceptions during temporary files removal, but I believe it would be better to find out why actual files removal fails.
Do you have any other exceptions in your log above this stack trace?
Temporary directory might be still locked by running Postgres process at the moment of removal, but the process must be killed already, so I suppose this could be the root of the problem.

[smecsia]

Please also indicate the version and the operating system, you're using.

[zemudkram]

I was going to say there are no other exceptions, but it does look like there is a null-pointer exception, which has overwritten a log line. There are also several warnings about not being able to delete the files. Here's a more complete log of a typical test run.

2016-02-27 09:43:54,899 [main] INFO  org.springframework.beans.factory.xml.XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [datasource-test-context.xml]
2016-02-27 09:43:55,480 [main] INFO  org.springframework.context.support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@12843fce: startup date [Sat Feb 27 09:43:55 NZDT 2016]; root of context hierarchy
2016-02-27 09:43:55,839 [main] INFO  org.springframework.beans.factory.support.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@c46bcd4: defining beans [postgresService,dataSource,dbCreator,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0,org.springframework.transaction.interceptor.TransactionInterceptor#0,org.springframework.transaction.config.internalTransactionAdvisor,transactionManager,transactionInterceptor,autoProxyCreator,channelDao,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor]; root of factory hierarchy
2016-02-27 09:44:04,424 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@6b927fb
2016-02-27 09:44:04,766 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@6ae5aa72
2016-02-27 09:44:05,767 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@222545dc
2016-02-27 09:44:05,768 [main] INFO  com.anzcro.o3.util.db.PostgresService - STARTED EMBEDDED POSTGRES - CONNECTION URL IS jdbc:postgresql://localhost:63844/test?user=test&password=test
2016-02-27 09:44:05,829 [main] INFO  org.springframework.jdbc.datasource.DriverManagerDataSource - Loaded JDBC driver: org.postgresql.Driver
2016-02-27 09:44:06,070 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@7530ad9c
2016-02-27 09:44:06,385 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@394df057
2016-02-27 09:44:06,684 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@65d09a04
2016-02-27 09:44:06,924 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@707194ba
2016-02-27 09:44:07,214 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@45b4c3a9
2016-02-27 09:44:08,075 [Thread-20] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-87fbeab3-089c-46cf-8b40-f5cd686f326e/pgsql/bin/psql.pid
2016-02-27 09:44:08,076 [Thread-31] INFO  org.springframework.context.support.GenericApplicationContext - Closing 

Here's the line with the NPE: I'm not sure where this NPE is coming from - fairly certain it's not from spring...grepping through the code of this project leads me to PostgresArtifactStore

org.springframework.context.support.GenericApplicationContext@12843fce: startup date [Sat Feb 27 09:43:55 NZDT 2016]; root of context hierarFailed to extract file set: java.lang.NullPointerException
chy

And continues

2016-02-27 09:44:08,076 [Thread-24] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-87fbeab3-089c-46cf-8b40-f5cd686f326e/pgsql/bin/psql.pid
2016-02-27 09:44:08,075 [Thread-12] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-87fbeab3-089c-46cf-8b40-f5cd686f326e/pgsql/bin/psql.pid
2016-02-27 09:44:08,075 [Thread-16] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-87fbeab3-089c-46cf-8b40-f5cd686f326e/pgsql/bin/psql.pid
2016-02-27 09:44:08,080 [Thread-31] INFO  org.springframework.context.support.DefaultLifecycleProcessor - Stopping beans in phase 0
2016-02-27 09:44:08,095 [Thread-1] INFO  de.flapdoodle.embed.process.runtime.ProcessControl - execSuccess: true [kill, -2, 88777]
Exception in thread "Thread-1" java.lang.IllegalStateException: Shutdown in progress
    at java.lang.ApplicationShutdownHooks.add(ApplicationShutdownHooks.java:66)
    at java.lang.Runtime.addShutdownHook(Runtime.java:211)
    at de.flapdoodle.embed.process.io.file.FileCleaner.forceDeleteOnExit(FileCleaner.java:52)
    at de.flapdoodle.embed.process.io.file.Files.forceDelete(Files.java:125)
    at ru.yandex.qatools.embed.postgresql.PostgresProcess.deleteTempFiles(PostgresProcess.java:157)
    at ru.yandex.qatools.embed.postgresql.PostgresProcess.stopInternal(PostgresProcess.java:117)
    at de.flapdoodle.embed.process.runtime.AbstractProcess.stop(AbstractProcess.java:170)
    at de.flapdoodle.embed.process.runtime.Executable.stop(Executable.java:73)
    at de.flapdoodle.embed.process.runtime.Executable$JobKiller.run(Executable.java:90)
    at java.lang.Thread.run(Thread.java:745)
2016-02-27 09:44:08,257 [Thread-1] WARN  de.flapdoodle.embed.process.io.file.Files - could not delete /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-87fbeab3-089c-46cf-8b40-f5cd686f326e/db-content-0412a790-1bdb-4460-8a5d-eed03e328b7e. Will try to delete it again when program exits.
2016-02-27 09:44:08,259 [Thread-31] INFO  org.springframework.beans.factory.support.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@c46bcd4: defining beans [postgresService,dataSource,dbCreator,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.transaction.annotation.AnnotationTransactionAttributeSource#0,org.springframework.transaction.interceptor.TransactionInterceptor#0,org.springframework.transaction.config.internalTransactionAdvisor,transactionManager,transactionInterceptor,autoProxyCreator,channelDao,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor]; root of factory hierarchy

Process finished with exit code 0

We are seeing this on MacOS (10.11) and Linux (Ubuntu 15.10 I think) - we haven't tried on Windows yet, since we're mainly a *nix shop.

Should I perhaps raise an issue over at flapdoodle as well?

[smecsia]

@zemudkram Thanks for the detailed explanation. It seems that I've managed to resolve this problem. Could you try the version from PR(#27) locally?

[zemudkram]

@smecsia 👍 Sure I will try this out Monday. Thanks for the quick response :)

[zemudkram]

Sorry, I've not been able to try this locally yet. I will give it a shot today.

[zemudkram]

@smecsia I've tested 1.10-SNAPSHOT from PR(#27) and the NPE is not there. So that part of the problem is fixed, I think.

Many of our tests extend from a base class that contains the spring context configuration and common set up code for a particular aspect of our project. When the tests are run individually, the context shuts down correctly, however when run as a suite (usually by selecting the package in my IDE and running all tests in the package) or as part of a maven test run, we still see the IllegalStateException (see stack trace below).

These tests are quite old, and perhaps it's not the best way to be using Spring contexts, but it's what we have to deal with at the moment. I'm inclined to think that this problem resides in the flapdoodle embedded process code, rather than the postgresql-embedded project though.

2016-03-01 08:54:49,357 [main] INFO  org.springframework.context.support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@6d8a00e3: startup date [Tue Mar 01 08:54:49 NZDT 2016]; root of context hierarchy
2016-03-01 08:54:49,567 [main] INFO  org.springframework.beans.factory.config.PropertyPlaceholderConfigurer - Loading properties file from class path resource [o3test.properties]
2016-03-01 08:54:49,628 [main] INFO  org.springframework.beans.factory.support.DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@3b088d51: defining beans [propertyPlaceholderConfigurerBusinessBase,postgresService,dbCreator,simpleJdbcTemplate,dataSource,superDataSource,transactionManager,transactionInterceptor,autoProxyCreator,...,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor]; root of factory hierarchy
2016-03-01 08:54:56,971 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@4567f35d
2016-03-01 08:54:57,315 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@6b81ce95
2016-03-01 08:54:58,319 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@2a798d51
2016-03-01 08:54:58,537 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@7f3b84b8
2016-03-01 08:54:58,847 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@7f0eb4b4
2016-03-01 08:54:59,160 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@c8c12ac
2016-03-01 08:54:59,409 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@4ec4f3a0
2016-03-01 08:54:59,678 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@9597028
2016-03-01 08:54:59,989 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@1b7cc17c
2016-03-01 08:55:00,293 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@67c27493
2016-03-01 08:55:00,511 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@5b8dfcc1
2016-03-01 08:55:00,729 [main] INFO  de.flapdoodle.embed.process.runtime.Executable - start ru.yandex.qatools.embed.postgresql.config.PostgresConfig@35e2d654
2016-03-01 08:55:00,815 [main] INFO  org.springframework.jdbc.datasource.DriverManagerDataSource - Loaded JDBC driver: org.postgresql.Driver

...testing....

2016-03-01 08:55:06,052 [Thread-32] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid
2016-03-01 08:55:06,052 [Thread-40] WARN  de.flapdoodle.embed.process.io.file.Files - could not delete /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid. Will try to delete it again when program exits.
2016-03-01 08:55:06,052 [Thread-47] INFO  org.springframework.context.support.GenericApplicationContext - Closing org.springframework.context.support.GenericApplicationContext@6d8a00e3: startup date [Tue Mar 01 08:54:49 NZDT 2016]; root of context hierarchy
2016-03-01 08:55:06,052 [Thread-20] WARN  de.flapdoodle.embed.process.io.file.Files - could not delete /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid. Will try to delete it again when program exits.
2016-03-01 08:55:06,052 [Thread-24] WARN  de.flapdoodle.embed.process.io.file.Files - could not delete /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid. Will try to delete it again when program exits.
2016-03-01 08:55:06,057 [Thread-47] INFO  org.springframework.context.support.DefaultLifecycleProcessor - Stopping beans in phase 0
2016-03-01 08:55:06,052 [Thread-12] WARN  de.flapdoodle.embed.process.io.file.Files - could not delete /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid. Will try to delete it again when program exits.
2016-03-01 08:55:06,053 [Thread-16] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid
2016-03-01 08:55:06,053 [Thread-36] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid
2016-03-01 08:55:06,053 [Thread-28] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/psql.pid
Exception in thread "Thread-40" java.lang.IllegalStateException: Shutdown in progress
    at java.lang.ApplicationShutdownHooks.add(ApplicationShutdownHooks.java:66)
    at java.lang.Runtime.addShutdownHook(Runtime.java:211)
    at de.flapdoodle.embed.process.io.file.FileCleaner.forceDeleteOnExit(FileCleaner.java:52)
    at de.flapdoodle.embed.process.io.file.Files.forceDelete(Files.java:125)
    at de.flapdoodle.embed.process.runtime.AbstractProcess.stop(AbstractProcess.java:173)
    at de.flapdoodle.embed.process.runtime.AbstractProcess$JobKiller.run(AbstractProcess.java:243)
    at java.lang.Thread.run(Thread.java:745)

2016-03-01 08:55:06,903 [Thread-6] INFO  de.flapdoodle.embed.process.runtime.ProcessControl - execSuccess: true [kill, -2, 37710]
2016-03-01 08:55:06,903 [Thread-6] WARN  de.flapdoodle.embed.process.runtime.AbstractProcess - Could not delete pid file: /var/folders/22/1f6xflcj60qgv_27xwtyxr1m0000gn/T/postgresql-embed-8b47014f-928d-4d22-b9a6-5f9428bf62f3/pgsql/bin/postgres.pid
2016-03-01 08:55:06,904 [Thread-47] INFO  org.springframework.beans.factory.support.DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@3b088d51: defining beans [propertyPlaceholderConfigurerBusinessBase,postgresService,dbCreator,simpleJdbcTemplate,dataSource,superDataSource,transactionManager,transactionInterceptor,autoProxyCreator,...,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor]; root of factory hierarchy

Process finished with exit code 0

[smecsia]

@zemudkram AFAIU you're using Spring4JUnitRunner (or a kind of) and the independent Spring context for each test class. That's why there are multiple messages about psql executable in the log.
I have some assumptions about the roots of your problem, but first I'd like to ask some questions.

1. Why don't you share the single Spring context between the tests and single PostgreSQL instance accordingly? This could save you the execution time and also could solve your troubles with the concurrency of instances.
2. How do you set the port number for each PostgreSQL instance? Is it randomly chosen or Postgres service chooses the first available?

Btw it would be great if you could create the example project, which would allow to reproduce the problem.