Self-test?

[Thorsten Glaser]

Hi *,

I’m running into a problem with a Maven plugin that uses the H2 database:

https://github.com/jeremylong/DependencyCheck/issues/2262

tl;dr: I’m getting “Unable to connect to the database” after it was created,

upstream says something about it being locked, and it’s massively larger

than expected (one order of magnitude).

Is there some way I can exercise a self-test of the H2 code, utilising the

~/.m2/repository/com/h2database/h2/1.4.196/h2-1.4.196.jar file used by it?

Thanks in advance,

//mirabilos
--
tarent solutions GmbH
Rochusstraße 2-4, D-53123 Bonn • http://www.tarent.de/
Tel: +49 228 54881-393 • Fax: +49 228 54881-235
HRB 5168 (AG Bonn) • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

**********

Mit der tarent Academy bieten wir auch Trainings und Schulungen in den
Bereichen Softwareentwicklung, Agiles Arbeiten und Zukunftstechnologien an.

Besuchen Sie uns auf www.tarent.de/academy. Wir freuen uns auf Ihren Kontakt.

**********

[Noel Grandin]

looks very similar to

https://github.com/h2database/h2database/issues/2152

so probably java is not liking virtualised storage for some reason

[Thorsten Glaser]

On Wed, 16 Oct 2019, Noel Grandin wrote:

> looks very similar to
>
> https://github.com/h2database/h2database/issues/2152

Hmm, no… lsof shows nothing is keeping the file open, and…

> so probably java is not liking virtualised storage for some reason

… this storage is not virtualised like in the Docker/cloud
scenario: it’s an emulated hard disc drive, on which a normal
ext4 filesystem is used locally.

Furthermore, the precisely same setup is also used by my
Jenkins instance, on which it works.

bye,

[Noel Grandin]

> … this storage is not virtualised like in the Docker/cloud
> scenario: it’s an emulated hard disc drive, on which a normal
> ext4 filesystem is used locally.
>

THe emulated part is possibly the problem - some filesystem related thing is re-using inode-no/device-no pairs, which
appears to confused the java locking (I'm guessing here)

[Thorsten Glaser]

On Wed, 16 Oct 2019, Noel Grandin wrote:

> THe emulated part is possibly the problem - some filesystem related thing is
> re-using inode-no/device-no pairs

Yes, I read this from the SMB reference, but this cannot happen
in this scenatio: from the operating system’s point of view, it’s
like a SCSI hard disc is plugged, and the filesystem is purely
local and has reliable inodes and device numbers.

[Thorsten Glaser]

On Wed, 16 Oct 2019, Thorsten Glaser wrote:

> tl;dr: I’m getting “Unable to connect to the database” after it was created,

I’ve discovered some more log:
~/.m2/repository/org/owasp/dependency-check-data/4.0/odc.trace.db

-----BEGIN cutting here may damage your screen surface-----
2019-10-16 13:16:15 database: close
org.h2.message.DbException: IO Exception: "Closing" [90028-196]
at org.h2.message.DbException.get(DbException.java:168)
at org.h2.mvstore.db.MVTableEngine$Store.close(MVTableEngine.java:397)
at org.h2.engine.Database.closeOpenFilesAndUnlock(Database.java:1397)
at org.h2.engine.Database.close(Database.java:1297)
at org.h2.engine.Database.removeSession(Database.java:1179)
at org.h2.engine.Session.close(Session.java:851)
at org.h2.command.dml.TransactionCommand.update(TransactionCommand.java:111)
at org.h2.command.CommandContainer.update(CommandContainer.java:101)
at org.h2.command.Command.executeUpdate(Command.java:260)
at org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:207)
at org.owasp.dependencycheck.data.nvdcve.CveDB.defrag(CveDB.java:1578)
at org.owasp.dependencycheck.Engine.doUpdates(Engine.java:928)
at org.owasp.dependencycheck.Engine.initializeAndUpdateDatabase(Engine.java:723)
at org.owasp.dependencycheck.Engine.analyzeDependencies(Engine.java:653)
at org.owasp.dependencycheck.maven.BaseDependencyCheckMojo.runCheck(BaseDependencyCheckMojo.java:1402)
at org.owasp.dependencycheck.maven.BaseDependencyCheckMojo.execute(BaseDependencyCheckMojo.java:801)
at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
at org.apache.maven.cli.MavenCli.execute(MavenCli.java:956)
at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
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.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:282)
at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:225)
at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:406)
at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:347)
Caused by: org.h2.jdbc.JdbcSQLException: IO Exception: "Closing" [90028-196]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
... 38 more
Caused by: java.lang.IllegalStateException: This map is closed [1.4.196/4]
at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:765)
at org.h2.mvstore.MVMap.beforeWrite(MVMap.java:1044)
at org.h2.mvstore.MVMap.copy(MVMap.java:1236)
at org.h2.mvstore.MVMap.copy(MVMap.java:1253)
at org.h2.mvstore.MVMap.copy(MVMap.java:1253)
at org.h2.mvstore.MVMap.copy(MVMap.java:1253)
at org.h2.mvstore.MVMap.copy(MVMap.java:1253)
at org.h2.mvstore.MVMap.copyFrom(MVMap.java:1223)
at org.h2.mvstore.MVStoreTool.compact(MVStoreTool.java:529)
at org.h2.mvstore.MVStoreTool.compact(MVStoreTool.java:494)
at org.h2.mvstore.MVStoreTool.compact(MVStoreTool.java:440)
at org.h2.mvstore.db.MVTableEngine$Store.close(MVTableEngine.java:386)
... 36 more
2019-10-16 13:16:16 database: flush
org.h2.message.DbException: General error: "java.lang.IllegalStateException: The file is locked: nio:/home/test/.m2/repository/org/owasp/dependency-check-data/4.0/odc.mv.db [1.4.196/7]" [50000-196]
at org.h2.message.DbException.get(DbException.java:168)
at org.h2.message.DbException.convert(DbException.java:295)
at org.h2.mvstore.db.MVTableEngine$1.uncaughtException(MVTableEngine.java:95)
at org.h2.mvstore.MVStore.panic(MVStore.java:378)
at org.h2.mvstore.MVStore.<init>(MVStore.java:361)
at org.h2.mvstore.MVStore$Builder.open(MVStore.java:2930)
at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:155)
at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:100)
at org.h2.engine.Database.getPageStore(Database.java:2476)
at org.h2.engine.Database.open(Database.java:697)
at org.h2.engine.Database.openDatabase(Database.java:276)
at org.h2.engine.Database.<init>(Database.java:270)
at org.h2.engine.Engine.openSession(Engine.java:64)
at org.h2.engine.Engine.openSession(Engine.java:176)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:154)
at org.h2.engine.Engine.createSession(Engine.java:137)
at org.h2.engine.Engine.createSession(Engine.java:27)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:354)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:116)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:100)
at org.h2.Driver.connect(Driver.java:69)
at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:677)
at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:228)
at org.owasp.dependencycheck.data.nvdcve.ConnectionFactory.initialize(ConnectionFactory.java:163)
at org.owasp.dependencycheck.data.nvdcve.ConnectionFactory.getConnection(ConnectionFactory.java:231)
at org.owasp.dependencycheck.data.nvdcve.CveDB.open(CveDB.java:387)
at org.owasp.dependencycheck.data.nvdcve.CveDB.<init>(CveDB.java:357)
at org.owasp.dependencycheck.Engine.openDatabase(Engine.java:1019)
at org.owasp.dependencycheck.Engine.doUpdates(Engine.java:937)
at org.owasp.dependencycheck.Engine.initializeAndUpdateDatabase(Engine.java:723)
at org.owasp.dependencycheck.Engine.analyzeDependencies(Engine.java:653)
at org.owasp.dependencycheck.maven.BaseDependencyCheckMojo.runCheck(BaseDependencyCheckMojo.java:1402)
at org.owasp.dependencycheck.maven.BaseDependencyCheckMojo.execute(BaseDependencyCheckMojo.java:801)
at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
at org.apache.maven.cli.MavenCli.execute(MavenCli.java:956)
at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
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.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:282)
at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:225)
at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:406)
at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:347)
Caused by: org.h2.jdbc.JdbcSQLException: General error: "java.lang.IllegalStateException: The file is locked: nio:/home/test/.m2/repository/org/owasp/dependency-check-data/4.0/odc.mv.db [1.4.196/7]" [50000-196]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
... 55 more
Caused by: java.lang.IllegalStateException: The file is locked: nio:/home/test/.m2/repository/org/owasp/dependency-check-data/4.0/odc.mv.db [1.4.196/7]
at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:765)
at org.h2.mvstore.FileStore.open(FileStore.java:168)
at org.h2.mvstore.MVStore.<init>(MVStore.java:347)
... 50 more
Caused by: java.nio.channels.OverlappingFileLockException
at java.base/sun.nio.ch.FileLockTable.checkList(FileLockTable.java:229)
at java.base/sun.nio.ch.FileLockTable.add(FileLockTable.java:123)
at java.base/sun.nio.ch.FileChannelImpl.tryLock(FileChannelImpl.java:1154)
at org.h2.store.fs.FileNio.tryLock(FilePathNio.java:121)
at java.base/java.nio.channels.FileChannel.tryLock(FileChannel.java:1165)
at org.h2.mvstore.FileStore.open(FileStore.java:165)
... 51 more
2019-10-16 13:16:16 database: flush
org.h2.message.DbException: General error: "java.lang.IllegalStateException: The file is locked: nio:/home/test/.m2/repository/org/owasp/dependency-check-data/4.0/odc.mv.db [1.4.196/7]" [50000-196]
at org.h2.message.DbException.get(DbException.java:168)
at org.h2.message.DbException.convert(DbException.java:295)
at org.h2.mvstore.db.MVTableEngine$1.uncaughtException(MVTableEngine.java:95)
at org.h2.mvstore.MVStore.panic(MVStore.java:378)
at org.h2.mvstore.MVStore.<init>(MVStore.java:361)
at org.h2.mvstore.MVStore$Builder.open(MVStore.java:2930)
at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:155)
at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:100)
at org.h2.engine.Database.getPageStore(Database.java:2476)
at org.h2.engine.Database.open(Database.java:697)
at org.h2.engine.Database.openDatabase(Database.java:276)
at org.h2.engine.Database.<init>(Database.java:270)
at org.h2.engine.Engine.openSession(Engine.java:64)
at org.h2.engine.Engine.openSession(Engine.java:176)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:154)
at org.h2.engine.Engine.createSession(Engine.java:137)
at org.h2.engine.Engine.createSession(Engine.java:27)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:354)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:116)
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:100)
at org.h2.Driver.connect(Driver.java:69)
at org.owasp.dependencycheck.data.nvdcve.DriverShim.connect(DriverShim.java:93)
at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:677)
at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:228)
at org.owasp.dependencycheck.data.nvdcve.ConnectionFactory.initialize(ConnectionFactory.java:163)
at org.owasp.dependencycheck.data.nvdcve.ConnectionFactory.getConnection(ConnectionFactory.java:231)
at org.owasp.dependencycheck.data.nvdcve.CveDB.open(CveDB.java:387)
at org.owasp.dependencycheck.data.nvdcve.CveDB.<init>(CveDB.java:357)
at org.owasp.dependencycheck.Engine.openDatabase(Engine.java:1019)
at org.owasp.dependencycheck.Engine.doUpdates(Engine.java:937)
at org.owasp.dependencycheck.Engine.initializeAndUpdateDatabase(Engine.java:723)
at org.owasp.dependencycheck.Engine.analyzeDependencies(Engine.java:653)
at org.owasp.dependencycheck.maven.BaseDependencyCheckMojo.runCheck(BaseDependencyCheckMojo.java:1402)
at org.owasp.dependencycheck.maven.BaseDependencyCheckMojo.execute(BaseDependencyCheckMojo.java:801)
at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156)
at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
at org.apache.maven.cli.MavenCli.execute(MavenCli.java:956)
at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
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.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:282)
at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:225)
at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:406)
at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:347)
Caused by: org.h2.jdbc.JdbcSQLException: General error: "java.lang.IllegalStateException: The file is locked: nio:/home/test/.m2/repository/org/owasp/dependency-check-data/4.0/odc.mv.db [1.4.196/7]" [50000-196]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
... 56 more
Caused by: java.lang.IllegalStateException: The file is locked: nio:/home/test/.m2/repository/org/owasp/dependency-check-data/4.0/odc.mv.db [1.4.196/7]
at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:765)
at org.h2.mvstore.FileStore.open(FileStore.java:168)
at org.h2.mvstore.MVStore.<init>(MVStore.java:347)
... 51 more
Caused by: java.nio.channels.OverlappingFileLockException
at java.base/sun.nio.ch.FileLockTable.checkList(FileLockTable.java:229)
at java.base/sun.nio.ch.FileLockTable.add(FileLockTable.java:123)
at java.base/sun.nio.ch.FileChannelImpl.tryLock(FileChannelImpl.java:1154)
at org.h2.store.fs.FileNio.tryLock(FilePathNio.java:121)
at java.base/java.nio.channels.FileChannel.tryLock(FileChannel.java:1165)
at org.h2.mvstore.FileStore.open(FileStore.java:165)
... 52 more
-----END cutting here may damage your screen surface-----

So the first exception is actually during “closing”.

Something for the H2 people: after the data is written to the database,
the OWASP plugin does a “database defragmentation” step which is taking
rather long. Unsure if that is involved, or what it even does.

bye,

[Noel Grandin]

that is some kind of corruption being triggered during the compact phase when the db closes.

you could work around that by disabling compaction, by appending ";MAX_COMPACT_TIME=0" to the connection URL

[Thorsten Glaser]

OWASP people, can you do something with the above info?
I’m just end user here…

[Thorsten Glaser]

On Wed, 16 Oct 2019, Hans Aikema wrote:

> @mirabilos You can try if this resolves the issue for your VM by
> @adding an environment variable to your maven command
>
> `mvn "-DconnectionString=jdbc:h2:file:%s;AUTOCOMMIT=ON;LOG=0;CACHE_SIZE=65536;MAX_COMPACT_TIME=0;" clean install`

Thanks… didn’t help any either.

> Using a freshly spun Debian 10 I could not reproduce your symptoms.

Yeah, somehow this doesn’t surprise me. Perhaps bit rot, even if the
“defective” VM also was freshly generated… *shrug* but that’s why I
asked for an H2 self-test.

If there’s one I’ll try that, otherwise I guess I’ll let the matter rest
and ship the software with the plugin disabled by default.

Thanks nevertheless,