clean-up of embedded process folder fails & incorrect console/log messages from "stopInternal"

I have created a maven-plugin that wraps around the postgresql-embedded component, using it to successfully start an embedded postgres process during the pre-integration phase of the maven lifecycle and stop/shutdown the process during the post-integration-phase of the lifecycle. I got the idea after posting this stackoverflow question and got a great response by user tunaki.

Doing my testing on Mac OSX (El Capitan/10.11.5) with maven Apache Maven 3.3.9 and java 8.

And, from my pom file:

    <dependency>
        <groupId>ru.yandex.qatools.embed</groupId>
        <artifactId>postgresql-embedded</artifactId>
        <version>1.16</version>
    </dependency>

I believe most of the functionality is working properly, except for the shutdown process. The code is managed by a PostgresEmbeddedService class. Here is what my start() method looks like:

public void start() throws Exception {
    DownloadConfigBuilder downloadConfigBuilder = new DownloadConfigBuilder();
    downloadConfigBuilder.defaultsForCommand(Command.Postgres);
    if (StringUtils.isNotEmpty(proxyHost) && proxyPort != null) {
        downloadConfigBuilder.proxyFactory(new HttpProxyFactory(proxyHost, proxyPort));
    }

    IRuntimeConfig runtimeConfig = new RuntimeConfigBuilder().defaults(Command.Postgres)
        .artifactStore(new ArtifactStoreBuilder().defaults(Command.Postgres).download(downloadConfigBuilder))
        .build();
    final PostgresStarter<PostgresExecutable, PostgresProcess> runtime = PostgresStarter.getInstance(runtimeConfig);
    Version dbVersion = Version.valueOf(this.version);

    final PostgresConfig configDb = new PostgresConfig(dbVersion, new Net(host, port), new Storage(dbName), 
        new Timeout(timeout), new Credentials(username, password));
    PostgresExecutable exec = runtime.prepare(configDb);
    postgresProcess = exec.start();
    this.mavenLog.debug("Embedded postgres process Started with PID: " + postgresProcess.getProcessId());
    started = true;
}

And, here is my stop() method:

public void stop() throws Exception {
    this.mavenLog.info("Attempting to Stop the Embedded Postgres process");
    if (!stopped) {
        if (postgresProcess != null) {
        this.mavenLog.debug("stopping Postgres process with PID: " + postgresProcess.getProcessId());
            started = false;
        postgresProcess.stop();
        postgresProcess = null;
        this.mavenLog.info("Stop of Embedded Postgres process Succeeded!");
        stopped = true;
            } else {
            this.mavenLog.info("Postgresql process does Not exist - Nothing to Stop!");
            }
        }
}

Note that postgresProcess is an instance member of the class. It is instantiated in start()and held in memory as long as the maven process continues until stop() is called in post-integration-test.

Here is the problem I am seeing. It seems that the process.stop() is kind of working, but outputs some confusing console/log output. Here is the excerpt from my maven console (in debug mode - first line is my log statement from my PostgresEmbeddedService class):

[INFO] Attempting to Stop the Embedded Postgres process
[DEBUG] stopping Postgres process with PID: 1043
Oct 27, 2016 7:07:43 PM ru.yandex.qatools.embed.postgresql.PostgresProcess stopInternal
INFO: trying to stop postgresql
[DEBUG] Detected pid: 1057
[INFO] start AbstractPostgresConfig{storage=Storage{dbDir=/var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549/db-content-a4949f8d-32a3-48b8-9d34-90d0c9cce4ff, dbName='blahblah', isTmpDir=true}, network=Net{host='localhost', port=5432}, timeout=Timeout{startupTimeout=30000}, credentials=Credentials{username='myUser', password='myPassword'}, args=[stop], additionalInitDbParams=[]}
[DEBUG] waiting for server to shut down....
[DEBUG]  done
server stopped

Oct 27, 2016 7:07:44 PM ru.yandex.qatools.embed.postgresql.PostgresProcess sendStopToPostgresqlInstance
INFO: Cleaning up after the embedded process (removing /var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549)...
[DEBUG] could delete /var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549
Oct 27, 2016 7:07:45 PM ru.yandex.qatools.embed.postgresql.PostgresProcess stopInternal
WARNING: could not stop postgresql with command, try next
[DEBUG] Detected pid: 1058
[INFO] stopOrDestroyProcess: process hasn't exited 

[INFO] execSuccess: false [kill, -2, 1043]
Oct 27, 2016 7:07:46 PM ru.yandex.qatools.embed.postgresql.PostgresProcess stopInternal
WARNING: could not stop postgresql, try next
[DEBUG] Detected pid: 1059
[INFO] stopOrDestroyProcess: process hasn't exited 

[INFO] execSuccess: false [kill, 1043]
Oct 27, 2016 7:07:46 PM ru.yandex.qatools.embed.postgresql.PostgresProcess stopInternal
WARNING: could not stop postgresql, try next
Oct 27, 2016 7:07:46 PM ru.yandex.qatools.embed.postgresql.PostgresProcess stopInternal
WARNING: could not stop postgresql the second time, try one last thing
Oct 27, 2016 7:07:46 PM ru.yandex.qatools.embed.postgresql.PostgresProcess deleteTempFiles
WARNING: Could not delete temp db dir: /var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549/db-content-a4949f8d-32a3-48b8-9d34-90d0c9cce4ff
[WARNING] Could not delete pid file: /var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549/pgsql/bin/postgres.pid
[INFO] Stop of Embedded Postgres process Succeeded!

That last line is log statement from my class PostgresEmbeddedService. It seems like the actual server process is indeed being stopped. When I acutally look for that process with PID 1043:

$ ps -1043
  PID TTY           TIME CMD

Also, please note this output at the very end of my maven run:

INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 01:47 min
[INFO] Finished at: 2016-10-27T19:07:46-04:00
[INFO] Final Memory: 90M/848M
[INFO] ------------------------------------------------------------------------
[WARNING] Could not delete pid file: /var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549/pgsql/bin/pg_ctl.pid
[WARNING] Could not delete pid file: /var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549/pgsql/bin/createdb.pid
[WARNING] Could not delete pid file: /var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549/pgsql/bin/initdb.pid
Exception in thread "Thread-7" java.lang.NoClassDefFoundError: de/flapdoodle/embed/process/extract/ExtractedFileSets
    at de.flapdoodle.embed.process.store.ArtifactStore.removeFileSet(ArtifactStore.java:90)
    at ru.yandex.qatools.embed.postgresql.ext.PostgresArtifactStore.removeFileSet(PostgresArtifactStore.java:65)
    at de.flapdoodle.embed.process.runtime.Executable.stop(Executable.java:77)
    at de.flapdoodle.embed.process.runtime.Executable$JobKiller.run(Executable.java:90)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassNotFoundException: de.flapdoodle.embed.process.extract.ExtractedFileSets
    at org.codehaus.plexus.classworlds.strategy.SelfFirstStrategy.loadClass(SelfFirstStrategy.java:50)
    at org.codehaus.plexus.classworlds.realm.ClassRealm.unsynchronizedLoadClass(ClassRealm.java:271)
    at org.codehaus.plexus.classworlds.realm.ClassRealm.loadClass(ClassRealm.java:247)
    at org.codehaus.plexus.classworlds.realm.ClassRealm.loadClass(ClassRealm.java:239)
    ... 5 more

Further, I also notice that the maven temp file (/var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T/postgresql-embed-9e977da4-fb54-414e-b5ca-566936bc4549) _has actually_ been cleaned up/removed:

$ pwd
/var/folders/8g/69wh31fn7nx3q81phwfdpld00000gn/T 
$ ls -l postgres*
ls: postgres*: No such file or directory

So, is this mainly an issue with logging? Is there some thread-related timing issue going on here? Is this stop() process working properly with only some bad logging messages?

It seems like the issue is logging/console output only, but I found the messages confusing.

Thanks in advance for any help/feedback.

--Aram

yandex-qatools / postgresql-embedded

clean-up of embedded process folder fails & incorrect console/log messages from "stopInternal" #50