search

joelittlejohn / embedmongo-maven-plugin

Maven plugin wrapper for the flapdoodle.de embedded MongoDB API
Apache License 2.0
88 stars 51 forks source link

Embedded mongo is shutdown before tests end #30

Closed jmisur closed 11 years ago

jmisur commented 11 years ago

Hi, I just tried out this plugin and it's cool! However, sometimes I got this error:

[INFO] --- embedmongo-maven-plugin:0.1.9:start (start) @ erp-impl ---
Downloading: http://repo.maven.apache.org/maven2/org/apache/maven/maven-project/2.0/maven-project-2.0.pom
Downloaded: http://repo.maven.apache.org/maven2/org/apache/maven/maven-project/2.0/maven-project-2.0.pom (2 KB at 34.7 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/org/apache/maven/maven-profile/2.0/maven-profile-2.0.pom
Downloaded: http://repo.maven.apache.org/maven2/org/apache/maven/maven-profile/2.0/maven-profile-2.0.pom (2 KB at 28.5 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/org/apache/maven/maven-model/2.0/maven-model-2.0.pom
Downloaded: http://repo.maven.apache.org/maven2/org/apache/maven/maven-model/2.0/maven-model-2.0.pom (3 KB at 50.0 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/org/apache/maven/maven-artifact-manager/2.0/maven-artifact-manager-2.0.pom
Downloaded: http://repo.maven.apache.org/maven2/org/apache/maven/maven-artifact-manager/2.0/maven-artifact-manager-2.0.pom (2 KB at 28.6 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/org/apache/maven/maven-repository-metadata/2.0/maven-repository-metadata-2.0.pom
Downloaded: http://repo.maven.apache.org/maven2/org/apache/maven/maven-repository-metadata/2.0/maven-repository-metadata-2.0.pom (2 KB at 24.0 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/org/apache/maven/maven-artifact/2.0/maven-artifact-2.0.pom
Downloaded: http://repo.maven.apache.org/maven2/org/apache/maven/maven-artifact/2.0/maven-artifact-2.0.pom (723 B at 15.3 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.mongo/1.31/de.flapdoodle.embed.mongo-1.31.pom
Downloaded: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.mongo/1.31/de.flapdoodle.embed.mongo-1.31.pom (7 KB at 148.5 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.process/1.27/de.flapdoodle.embed.process-1.27.pom
Downloaded: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.process/1.27/de.flapdoodle.embed.process-1.27.pom (9 KB at 190.1 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/commons-io/commons-io/2.2/commons-io-2.2.pom
Downloaded: http://repo.maven.apache.org/maven2/commons-io/commons-io/2.2/commons-io-2.2.pom (11 KB at 207.2 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/org/apache/commons/commons-compress/1.3/commons-compress-1.3.pom
Downloaded: http://repo.maven.apache.org/maven2/org/apache/commons/commons-compress/1.3/commons-compress-1.3.pom (11 KB at 227.4 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/com/google/guava/guava/11.0.1/guava-11.0.1.pom
Downloaded: http://repo.maven.apache.org/maven2/com/google/guava/guava/11.0.1/guava-11.0.1.pom (6 KB at 116.1 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/com/google/guava/guava-parent/11.0.1/guava-parent-11.0.1.pom
Downloaded: http://repo.maven.apache.org/maven2/com/google/guava/guava-parent/11.0.1/guava-parent-11.0.1.pom (2 KB at 40.7 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/org/codehaus/plexus/plexus-utils/1.0.4/plexus-utils-1.0.4.jar
Downloading: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.mongo/1.31/de.flapdoodle.embed.mongo-1.31.jar
Downloading: http://repo.maven.apache.org/maven2/org/apache/commons/commons-compress/1.3/commons-compress-1.3.jar
Downloading: http://repo.maven.apache.org/maven2/commons-io/commons-io/2.2/commons-io-2.2.jar
Downloading: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.process/1.27/de.flapdoodle.embed.process-1.27.jar
Downloaded: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.mongo/1.31/de.flapdoodle.embed.mongo-1.31.jar (47 KB at 349.5 KB/sec)
Downloading: http://repo.maven.apache.org/maven2/com/google/guava/guava/11.0.1/guava-11.0.1.jar
Downloaded: http://repo.maven.apache.org/maven2/de/flapdoodle/embed/de.flapdoodle.embed.process/1.27/de.flapdoodle.embed.process-1.27.jar (86 KB at 571.0 KB/sec)
Downloaded: http://repo.maven.apache.org/maven2/commons-io/commons-io/2.2/commons-io-2.2.jar (170 KB at 997.2 KB/sec)
Downloaded: http://repo.maven.apache.org/maven2/org/codehaus/plexus/plexus-utils/1.0.4/plexus-utils-1.0.4.jar (160 KB at 850.9 KB/sec)
Downloaded: http://repo.maven.apache.org/maven2/org/apache/commons/commons-compress/1.3/commons-compress-1.3.jar (220 KB at 1130.3 KB/sec)
Downloaded: http://repo.maven.apache.org/maven2/com/google/guava/guava/11.0.1/guava-11.0.1.jar (1612 KB at 5574.8 KB/sec)
Sep 10, 2013 11:39:25 AM de.flapdoodle.embed.process.store.ArtifactStoreBuilder build
SEVERE: Build ArtifactStore(useCache:true)
[WARNING] Unrecognised MongoDB version '2.4.6', this might be a new version that we don't yet know about. Attemping download anyway...
Download GenericVersion{2.4.6}:Linux:B64 START
Download GenericVersion{2.4.6}:Linux:B64 DownloadSize: 94940554
Download GenericVersion{2.4.6}:Linux:B64 0% 1% 2% 3% 4% 5% 6% 7% 8% 9% 10% 11% 12% 13% 14% 15% 16% 17% 18% 19% 20% 21% 22% 23% 24% 25% 26% 27% 28% 29% 30% 31% 32% 33% 34% 35% 36% 37% 38% 39% 40% 41% 42% 43% 44% 45% 46% 47% 48% 49% 50% 51% 52% 53% 54% 55% 56% 57% 58% 59% 60% 61% 62% 63% 64% 65% 66% 67% 68% 69% 70% 71% 72% 73% 74% 75% 76% 77% 78% 79% 80% 81% 82% 83% 84% 85% 86% 87% 88% 89% 90% 91% 92% 93% 94% 95% 96% 97% 98% 99% 100% Download GenericVersion{2.4.6}:Linux:B64 DONE
Extract /opt/jenkins/jenkins_home/.embedmongo/linux/mongodb-linux-x86_64-2.4.6.tgz START
Extract /opt/jenkins/jenkins_home/.embedmongo/linux/mongodb-linux-x86_64-2.4.6.tgz DONE
[mongod output]note: noprealloc may hurt performance in many applications
[mongod output] Tue Sep 10 11:39:30.567 BackgroundJob starting: DataFileSync
[mongod output] Tue Sep 10 11:39:30.567 versionArrayTest passed
[mongod output] Tue Sep 10 11:39:30.567 shardKeyTest passed
[mongod output] Tue Sep 10 11:39:30.567 isInRangeTest passed
[mongod output] Tue Sep 10 11:39:30.567 shardObjTest passed
[mongod output] Tue Sep 10 11:39:30.583 [initandlisten] MongoDB starting : pid=17132 port=27017 dbpath=/tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c 64-bit host=INTPAY-T1
[mongod output] Tue Sep 10 11:39:30.583 [initandlisten] db version v2.4.6
[mongod output] Tue Sep 10 11:39:30.583 [initandlisten] git version: b9925db5eac369d77a3a5f5d98a145eaaacd9673
[mongod output] Tue Sep 10 11:39:30.583 [initandlisten] build info: Linux ip-10-2-29-40 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_49
[mongod output] Tue Sep 10 11:39:30.583 [initandlisten] allocator: tcmalloc
[mongod output] Tue Sep 10 11:39:30.583 [initandlisten] options: { dbpath: "/tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c", noauth: true, nohttpinterface: true, nojournal: true, noprealloc: true, port: 27017, smallfiles: true, verbose: true }
[mongod output] Tue Sep 10 11:39:30.631 [initandlisten] flushing directory /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c
[mongod output] Tue Sep 10 11:39:30.661 [initandlisten] opening db:  local
[mongod output] Tue Sep 10 11:39:30.661 [initandlisten] enter repairDatabases (to check pdfile version #)
[mongod output] Tue Sep 10 11:39:30.661 [initandlisten] done repairDatabases
[mongod output] Tue Sep 10 11:39:30.661 BackgroundJob starting: snapshot
[mongod output] Tue Sep 10 11:39:30.661 BackgroundJob starting: PeriodicTask::Runner
[mongod output] Tue Sep 10 11:39:30.661 BackgroundJob starting: ClientCursorMonitor
[mongod output] Tue Sep 10 11:39:30.661 [initandlisten] run command local.$cmd { create: "startup_log", size: 10485760, capped: true }
[mongod output] Tue Sep 10 11:39:30.661 [initandlisten] create collection local.startup_log { create: "startup_log", size: 10485760, capped: true }
[mongod output] Tue Sep 10 11:39:30.661 [FileAllocator] allocating new datafile /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c/local.ns, filling with zeroes...
[mongod output] Tue Sep 10 11:39:30.661 [FileAllocator] creating directory /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c/_tmp
[mongod output] Tue Sep 10 11:39:30.661 [FileAllocator] flushing directory /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c
[mongod output] Tue Sep 10 11:39:30.662 BackgroundJob starting: TTLMonitor
[mongod output] Tue Sep 10 11:39:30.694 [FileAllocator] flushing directory /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c
[mongod output] Tue Sep 10 11:39:30.719 [FileAllocator] done allocating datafile /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c/local.ns, size: 16MB,  took 0.025 secs
[mongod output] Tue Sep 10 11:39:30.719 [FileAllocator] allocating new datafile /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c/local.0, filling with zeroes...
[mongod output] Tue Sep 10 11:39:30.719 [FileAllocator] flushing directory /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c
[mongod output] Tue Sep 10 11:39:30.736 [FileAllocator] done allocating datafile /tmp/embedmongo-db-5a0789bd-f03b-4713-b8af-ec2f9afad64c/local.0, size: 16MB,  took 0.016 secs
[mongod output] Tue Sep 10 11:39:30.737 [initandlisten] allocExtent local.startup_log size 10485760 0
[mongod output] Tue Sep 10 11:39:30.737 [initandlisten] New namespace: local.startup_log
[mongod output] Tue Sep 10 11:39:30.738 [initandlisten] allocExtent local.system.namespaces size 5888 0
[mongod output] Tue Sep 10 11:39:30.738 [initandlisten] New namespace: local.system.namespaces
[mongod output] Tue Sep 10 11:39:30.738 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0  reslen:37 76ms
[mongod output] Tue Sep 10 11:39:30.738 [initandlisten] insert local.startup_log ninserted:1 keyUpdates:0  0ms
[mongod output] Tue Sep 10 11:39:30.738 [initandlisten] fd limit hard:8192 soft:8192 max conn: 6553
[mongod output] Tue Sep 10 11:39:30.738 [initandlisten] waiting for connections on port 27017
[INFO] 
[INFO] --- maven-surefire-plugin:2.15:test (integration-tests) @ erp-impl ---

... few tests run ok ...

[mongod output] Tue Sep 10 11:39:36.390 [initandlisten] connection accepted from 127.0.0.1:47733 #2 (2 connections now open)
[mongod output] Tue Sep 10 11:39:36.391 [conn2] run command admin.$cmd { shutdown: 1, force: true }
[mongod output] Tue Sep 10 11:39:36.391 [conn2] terminating, shutdown command received
[mongod output] Tue Sep 10 11:39:36.391 dbexit: shutdown called
[mongod output] Tue Sep 10 11:39:36.391 [conn2] shutdown: going to close listening sockets...
[mongod output] Tue Sep 10 11:39:36.391 [conn2] closing listening socket: 7
[mongod output] Tue Sep 10 11:39:36.391 [conn2] closing listening socket: 8
[mongod output] Tue Sep 10 11:39:36.391 [conn2] removing socket file: /tmp/mongodb-27017.sock
[mongod output] Tue Sep 10 11:39:36.391 [conn2] shutdown: going to flush diaglog...
[mongod output] Tue Sep 10 11:39:36.391 [conn2] shutdown: going to close sockets...
[mongod output] Tue Sep 10 11:39:36.391 [conn2] shutdown: waiting for fs preallocator...
[mongod output] Tue Sep 10 11:39:36.391 [conn2] shutdown: closing all files...
[mongod output] Tue Sep 10 11:39:36.391 [conn1] got request after shutdown()
[mongod output] Tue Sep 10 11:39:36.391 [conn2] closeAllFiles() finished
[mongod output] Tue Sep 10 11:39:36.391 [conn2] shutdown: removing fs lock...
[mongod output] Tue Sep 10 11:39:36.391 dbexit: really exiting now
[mongod output] 
Sep 10, 2013 9:39:36 AM com.mongodb.DBPortPool gotError
WARNING: emptying DBPortPool to localhost/127.0.0.1:27017 b/c of error
java.io.EOFException
    at org.bson.io.Bits.readFully(Bits.java:48)
    at org.bson.io.Bits.readFully(Bits.java:33)
    at org.bson.io.Bits.readFully(Bits.java:28)
    at com.mongodb.Response.<init>(Response.java:40)
    at com.mongodb.DBPort.go(DBPort.java:142)
    at com.mongodb.DBPort.call(DBPort.java:92)
    at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:244)
    at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:216)
    at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:288)
    at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:273)
    at com.mongodb.DBCollection.findOne(DBCollection.java:347)
    at com.mongodb.DBCollection.findOne(DBCollection.java:332)
    at com.mongodb.DBRefBase.fetch(DBRefBase.java:53)
    at org.springframework.data.mongodb.core.convert.MappingMongoConverter.readCollectionOrArray(MappingMongoConverter.java:743)

... subsequent tests fail on read/write ...

First it occured during first run of the plugin, then it ran successfully, then 3rd run also failed. Nothing was changed in between, seems like random behavior. My tests are plain simple read/write, nothing special.

My maven config:

        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-surefire-plugin</artifactId>
                <configuration>
                    <skip>true</skip>
                    <trimStackTrace>false</trimStackTrace>
                </configuration>
                <executions>
                    <execution>
                        <id>unit-tests</id>
                        <phase>test</phase>
                        <goals>
                            <goal>test</goal>
                        </goals>
                        <configuration>
                            <skip>false</skip>
                            <includes>
                                <include>**/*Test.java</include>
                            </includes>
                            <excludes>
                                <exclude>**/*IntegrationTest.java</exclude>
                            </excludes>
                        </configuration>
                    </execution>
                    <execution>
                        <id>integration-tests</id>
                        <phase>integration-test</phase>
                        <goals>
                            <goal>test</goal>
                        </goals>
                        <configuration>
                            <skip>false</skip>
                            <includes>
                                <include>**/*IntegrationTest.java</include>
                            </includes>
                        </configuration>
                    </execution>
                </executions>
            </plugin>
            <plugin>
                <groupId>com.github.joelittlejohn.embedmongo</groupId>
                <artifactId>embedmongo-maven-plugin</artifactId>
                <version>0.1.9</version>
                <executions>
                    <execution>
                        <id>start</id>
                        <goals>
                            <goal>start</goal>
                        </goals>
                        <configuration>
                            <version>2.4.6</version>
                        </configuration>
                    </execution>
                    <execution>
                        <id>stop</id>
                        <goals>
                            <goal>stop</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
jmisur commented 11 years ago

Correction: 3rd run was also successful, so it happened only during first run when the dependencies were downloaded.

joelittlejohn commented 11 years ago

I haven't seen this kind of behaviour before, although I always run integration tests with the maven-failsafe-plugin instead of the maven-surefire-plugin (I don't see why this would make any difference though). It looks like the mongo server has received an instruction to shut down.

Are you running any kind of parallel build? If so, is it possible that you have parallel instances of the plugin sharing the same port? This could also occur if you run multiple separate maven builds (if the same mongo port is used).

jmisur commented 11 years ago

It wasn't parallel build for sure, because it run just for the first time only on one branch. I will try to use another plugin, however the problem didn't occur anymore, so this ticket is effectively invalid until it will happen to somebody again. Maybe just one of a kind coincidence.

joelittlejohn commented 11 years ago

Okay I'll close the issue for now. I think something on your system sent mongo an instruction to shutdown.