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

TestDiskFull: The file is locked #1212

Closed
katzyn opened this issue Jun 17, 2018 · 28 comments
Closed

TestDiskFull: The file is locked #1212

katzyn opened this issue Jun 17, 2018 · 28 comments

Comments

@katzyn
Copy link
Contributor

katzyn commented Jun 17, 2018

Sometimes TestDiskFull fails because lock cannot be acquired. It's very strange, in should acquire a an exclusive lock in FileMemData and release it when connection is closed.

09:17:22 00:00.367 org.h2.test.synth.TestDiskFull FAIL org.h2.jdbc.JdbcSQLException: Database may be already in use: null. Possible solutions: close all other connection(s); use the server mode [90020-197]
ERROR: FAIL (mvStore memory multiThreaded ) org.h2.jdbc.JdbcSQLException: Database may be already in use: null. Possible solutions: close all other connection(s); use the server mode [90020-197] org.h2.jdbc.JdbcSQLException: Database may be already in use: null. Possible solutions: close all other connection(s); use the server mode [90020-197] ------------------------------
org.h2.jdbc.JdbcSQLException: Database may be already in use: null. Possible solutions: close all other connection(s); use the server mode [90020-197]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:379)
	at org.h2.message.DbException.get(DbException.java:167)
	at org.h2.mvstore.db.MVTableEngine$Store.convertIllegalStateException(MVTableEngine.java:187)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:167)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:94)
	at org.h2.engine.Database.getPageStore(Database.java:2565)
	at org.h2.engine.Database.open(Database.java:733)
	at org.h2.engine.Database.openDatabase(Database.java:309)
	at org.h2.engine.Database.<init>(Database.java:303)
	at org.h2.engine.Engine.openSession(Engine.java:69)
	at org.h2.engine.Engine.openSession(Engine.java:200)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
	at org.h2.engine.Engine.createSession(Engine.java:161)
	at org.h2.engine.Engine.createSession(Engine.java:31)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:335)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:125)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:104)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql.DriverManager.getConnection(DriverManager.java:571)
	at java.sql.DriverManager.getConnection(DriverManager.java:233)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:121)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:45)
	at org.h2.test.TestBase.runTest(TestBase.java:143)
	at org.h2.test.TestAll.addTest(TestAll.java:989)
	at org.h2.test.TestAll.test(TestAll.java:846)
	at org.h2.test.TestAll.runTests(TestAll.java:613)
	at org.h2.test.TestAll.testAll(TestAll.java:555)
	at org.h2.test.TestAll.run(TestAll.java:505)
	at org.h2.test.TestAll.main(TestAll.java:446)
Caused by: java.lang.IllegalStateException: The file is locked: unstable:memFS:/diskFull18.mv.db [1.4.197/7]
	at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:880)
	at org.h2.mvstore.FileStore.open(FileStore.java:171)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:369)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3206)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:155)
	... 25 more
@andreitokar
Copy link
Contributor

But whenever I see this, it's always unstable:memFS:/diskFull18.mv.db, meaning in=memory. Maybe it gets full for real - throws OOME and catches it, but memFS file system gets corrupted?
I would try to replicate it with -XX:+ExitOnOutOfMemory to see if it was OOME.

@grandinj
Copy link
Contributor

I'm guessing that one of our shutdown paths does not close the filechannel, perhaps because of the OOME @andreitokar mentions

@andreitokar
Copy link
Contributor

Then we would see that exception with real (i.e. FilePathNio), and not just in-memory (FilePathMem) file system. It might be that just that file system itself fails on OOME.

@grandinj
Copy link
Contributor

If I run TestDiskFull with -Xmx64M, I can't reproduce this error, instead I get:

Exception in thread "main" org.h2.jdbc.JdbcSQLException: General error: "java.lang.RuntimeException: Incompatible key type, expected org.h2.mvstore.db.ValueDataType@fffecd71 but got org.h2.mvstore.type.ObjectDataType@1bf8050 for index IDX_NAME" [50000-197]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:394)
at org.h2.message.DbException.get(DbException.java:171)
at org.h2.message.DbException.convert(DbException.java:311)
at org.h2.engine.Database.openDatabase(Database.java:335)
at org.h2.engine.Database.(Database.java:303)
at org.h2.engine.Engine.openSession(Engine.java:69)
at org.h2.engine.Engine.openSession(Engine.java:200)
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
at org.h2.engine.Engine.createSession(Engine.java:161)
at org.h2.engine.Engine.createSession(Engine.java:1)
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:335)
at org.h2.jdbc.JdbcConnection.(JdbcConnection.java:125)
at org.h2.jdbc.JdbcConnection.(JdbcConnection.java:104)
at org.h2.Driver.connect(Driver.java:69)
at java.sql.DriverManager.getConnection(DriverManager.java:664)
at java.sql.DriverManager.getConnection(DriverManager.java:270)
at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:128)
at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
Caused by: java.lang.RuntimeException: Incompatible key type, expected org.h2.mvstore.db.ValueDataType@fffecd71 but got org.h2.mvstore.type.ObjectDataType@1bf8050 for index IDX_NAME
at org.h2.message.DbException.throwInternalError(DbException.java:257)
at org.h2.mvstore.db.MVSecondaryIndex.(MVSecondaryIndex.java:71)
at org.h2.mvstore.db.MVTable.addIndex(MVTable.java:524)
at org.h2.command.ddl.CreateIndex.update(CreateIndex.java:107)
at org.h2.engine.MetaRecord.execute(MetaRecord.java:60)
at org.h2.engine.Database.open(Database.java:803)
at org.h2.engine.Database.openDatabase(Database.java:309)
... 15 more

@katzyn
Copy link
Contributor Author

katzyn commented Jul 5, 2018

@retomerz
Copy link
Contributor

retomerz commented Nov 8, 2018

@andreitokar
Copy link
Contributor

This happens all the time (i.e yesterday I saw it twice). When OOME happened, all bets are off, anything is possible, including in-memory file system corruption, which would lead to outstanding lock. Unless we manage to pre-allocate enough memory for this "file system", this test is no good.

@katzyn
Copy link
Contributor Author

katzyn commented Nov 13, 2018

I saw a lot of failures too in the last few days.

@katzyn
Copy link
Contributor Author

katzyn commented Dec 14, 2018

I can reproduce this failure on my system if this test is invoked in a loop.

There are 5 additional lines in modified TestDiskFull compared with current master branch, so line 84 in the stack trace is a line 79 in a master.

Normal call sequence:

tryLock memFS:/diskFull88.mv.db
	at org.h2.store.fs.FileMem.tryLock
	at org.h2.test.utils.FileUnstable.tryLock(FilePathUnstable.java:300)
	at java.base/java.nio.channels.FileChannel.tryLock(FileChannel.java:1160)
	at org.h2.mvstore.FileStore.open(FileStore.java:163)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:371)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3221)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:156)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:95)
	at org.h2.engine.Database.getPageStore(Database.java:2669)
	at org.h2.engine.Database.open(Database.java:753)
	at org.h2.engine.Database.openDatabase(Database.java:319)
	at org.h2.engine.Database.<init>(Database.java:313)
	at org.h2.engine.Engine.openSession(Engine.java:69)
	at org.h2.engine.Engine.openSession(Engine.java:200)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
	at org.h2.engine.Engine.createSession(Engine.java:161)
	at org.h2.engine.Engine.createSession(Engine.java:1)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:336)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:678)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:252)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:69)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
implCloseChannel memFS:/diskFull88.mv.db
	at org.h2.store.fs.FileMem.implCloseChannel
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.test.utils.FileUnstable.implCloseChannel(FilePathUnstable.java:229)
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.mvstore.FileStore.close(FileStore.java:195)
	at org.h2.mvstore.MVStore.closeStore(MVStore.java:966)
	at org.h2.mvstore.MVStore.close(MVStore.java:924)
	at org.h2.mvstore.db.MVTableEngine$Store.close(MVTableEngine.java:375)
	at org.h2.engine.Database.closeOpenFilesAndUnlock(Database.java:1552)
	at org.h2.engine.Database.close(Database.java:1449)
	at org.h2.engine.Database.removeSession(Database.java:1333)
	at org.h2.engine.Session.close(Session.java:890)
	at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:411)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:84)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
tryLock memFS:/diskFull89.mv.db
	at org.h2.store.fs.FileMem.tryLock
	at org.h2.test.utils.FileUnstable.tryLock(FilePathUnstable.java:300)
	at java.base/java.nio.channels.FileChannel.tryLock(FileChannel.java:1160)
	at org.h2.mvstore.FileStore.open(FileStore.java:163)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:371)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3221)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:156)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:95)
	at org.h2.engine.Database.getPageStore(Database.java:2669)
	at org.h2.engine.Database.open(Database.java:753)
	at org.h2.engine.Database.openDatabase(Database.java:319)
	at org.h2.engine.Database.<init>(Database.java:313)
	at org.h2.engine.Engine.openSession(Engine.java:69)
	at org.h2.engine.Engine.openSession(Engine.java:200)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
	at org.h2.engine.Engine.createSession(Engine.java:161)
	at org.h2.engine.Engine.createSession(Engine.java:1)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:336)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:678)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:252)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:69)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
implCloseChannel memFS:/diskFull89.mv.db
	at org.h2.store.fs.FileMem.implCloseChannel
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.test.utils.FileUnstable.implCloseChannel(FilePathUnstable.java:229)
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.mvstore.FileStore.close(FileStore.java:195)
	at org.h2.mvstore.MVStore.closeStore(MVStore.java:966)
	at org.h2.mvstore.MVStore.close(MVStore.java:924)
	at org.h2.mvstore.db.MVTableEngine$Store.close(MVTableEngine.java:375)
	at org.h2.engine.Database.closeOpenFilesAndUnlock(Database.java:1552)
	at org.h2.engine.Database.close(Database.java:1449)
	at org.h2.engine.Database.removeSession(Database.java:1333)
	at org.h2.engine.Session.close(Session.java:890)
	at org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:411)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:84)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)

Call sequence with a failure:

tryLock memFS:/diskFull19.mv.db
	at org.h2.store.fs.FileMem.tryLock
	at org.h2.test.utils.FileUnstable.tryLock(FilePathUnstable.java:300)
	at java.base/java.nio.channels.FileChannel.tryLock(FileChannel.java:1160)
	at org.h2.mvstore.FileStore.open(FileStore.java:163)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:371)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3221)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:156)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:95)
	at org.h2.engine.Database.getPageStore(Database.java:2669)
	at org.h2.engine.Database.open(Database.java:753)
	at org.h2.engine.Database.openDatabase(Database.java:319)
	at org.h2.engine.Database.<init>(Database.java:313)
	at org.h2.engine.Engine.openSession(Engine.java:69)
	at org.h2.engine.Engine.openSession(Engine.java:200)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
	at org.h2.engine.Engine.createSession(Engine.java:161)
	at org.h2.engine.Engine.createSession(Engine.java:1)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:336)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:678)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:252)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:69)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
tryLock memFS:/diskFull19.mv.db
	at org.h2.store.fs.FileMem.tryLock
	at org.h2.test.utils.FileUnstable.tryLock(FilePathUnstable.java:300)
	at java.base/java.nio.channels.FileChannel.tryLock(FileChannel.java:1160)
	at org.h2.mvstore.FileStore.open(FileStore.java:163)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:371)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3221)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:156)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:95)
	at org.h2.engine.Database.getPageStore(Database.java:2669)
	at org.h2.engine.Database.open(Database.java:753)
	at org.h2.engine.Database.openDatabase(Database.java:319)
	at org.h2.engine.Database.<init>(Database.java:313)
	at org.h2.engine.Engine.openSession(Engine.java:69)
	at org.h2.engine.Engine.openSession(Engine.java:200)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
	at org.h2.engine.Engine.createSession(Engine.java:161)
	at org.h2.engine.Engine.createSession(Engine.java:1)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:336)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:678)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:252)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:127)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
implCloseChannel memFS:/diskFull19.mv.db
	at org.h2.store.fs.FileMem.implCloseChannel
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.test.utils.FileUnstable.implCloseChannel(FilePathUnstable.java:229)
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.mvstore.FileStore.close(FileStore.java:195)
	at org.h2.mvstore.FileStore.open(FileStore.java:171)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:371)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3221)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:156)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:95)
	at org.h2.engine.Database.getPageStore(Database.java:2669)
	at org.h2.engine.Database.open(Database.java:753)
	at org.h2.engine.Database.openDatabase(Database.java:319)
	at org.h2.engine.Database.<init>(Database.java:313)
	at org.h2.engine.Engine.openSession(Engine.java:69)
	at org.h2.engine.Engine.openSession(Engine.java:200)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
	at org.h2.engine.Engine.createSession(Engine.java:161)
	at org.h2.engine.Engine.createSession(Engine.java:1)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:336)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:678)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:252)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:127)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
Exception in thread "main" org.h2.jdbc.JdbcSQLNonTransientConnectionException: Database may be already in use: null. Possible solutions: close all other connection(s); use the server mode [90020-197]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:611)
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:423)
	at org.h2.message.DbException.get(DbException.java:190)
	at org.h2.mvstore.db.MVTableEngine$Store.convertIllegalStateException(MVTableEngine.java:187)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:167)
	at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:95)
	at org.h2.engine.Database.getPageStore(Database.java:2669)
	at org.h2.engine.Database.open(Database.java:753)
	at org.h2.engine.Database.openDatabase(Database.java:319)
	at org.h2.engine.Database.<init>(Database.java:313)
	at org.h2.engine.Engine.openSession(Engine.java:69)
	at org.h2.engine.Engine.openSession(Engine.java:200)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:178)
	at org.h2.engine.Engine.createSession(Engine.java:161)
	at org.h2.engine.Engine.createSession(Engine.java:1)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:336)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:124)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:103)
	at org.h2.Driver.connect(Driver.java:69)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:678)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:252)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:127)
	at org.h2.test.synth.TestDiskFull.test(TestDiskFull.java:51)
	at org.h2.test.synth.TestDiskFull.main(TestDiskFull.java:35)
Caused by: java.lang.IllegalStateException: The file is locked: unstable:memFS:/diskFull19.mv.db [1.4.197/7]
	at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:881)
	at org.h2.mvstore.FileStore.open(FileStore.java:172)
	at org.h2.mvstore.MVStore.<init>(MVStore.java:371)
	at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3221)
	at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:156)
	... 19 more
implCloseChannel memFS:/diskFull19.mv.db
	at org.h2.store.fs.FileMem.implCloseChannel
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.test.utils.FileUnstable.implCloseChannel(FilePathUnstable.java:229)
	at java.base/java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:112)
	at org.h2.mvstore.FileStore.close(FileStore.java:195)
	at org.h2.mvstore.MVStore.closeStore(MVStore.java:966)
	at org.h2.mvstore.MVStore.closeImmediately(MVStore.java:933)
	at org.h2.mvstore.MVStore.panic(MVStore.java:424)
	at org.h2.mvstore.MVStore.write(MVStore.java:901)
	at org.h2.mvstore.MVStore.storeNow(MVStore.java:1282)
	at org.h2.mvstore.MVStore.store(MVStore.java:1140)
	at org.h2.mvstore.MVStore.tryCommit(MVStore.java:1085)
	at org.h2.mvstore.MVStore.writeInBackground(MVStore.java:2686)
	at org.h2.mvstore.MVStore$BackgroundWriterThread.run(MVStore.java:3000)

It means that underlying storage was not properly closed in a first part of test(int) method.

We either have a code path in this method that may lead to leaked connection or JdbcConnection.close() has similar problem, a call sequence with a failure has a close attempt from MVStore.BackgroundWriterThread unlike a normal one.

@katzyn
Copy link
Contributor Author

katzyn commented Dec 14, 2018

Before the failure JdbcConnection.close() is invoked from a finally block in TestDiskFull.test(int), but FileMem.implCloseChannel() is not invoked by this method for a some reason. Something is wrong with database shutdown logic.

Unfortunately, I cannot reproduce this problem when JVM is debugged.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

I can reproduce this issue on my system if TestDiskFull is invoked in a loop on Java 11 with -Xmx64M after a lot of iterations. It is also reproducible immediately on the first iteration with -Xmx24M.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

However, this issue is not reproducible with attached debugger.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

This issue is also not reproducible with debug print in FileMemData.tryLock() and FileMemData.unlock().

It looks like this issue appears when store is not closed together with connection, but is closed later from background writer thread. When TestDiskFull tries to reopen the database this thread is still alive and underlying storage is still locked.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

Why MVStore.stopBackgroundThread() is entered with different locked objects? Database+Session+other, Engine+Database+other, Session+Engine.

However, I don't see how background writer thread may prevent database shutdown process. I checked with debug print that previous connection is closed and background writer thread is still alive before the failure. It looks like only connection is closed, but database is not properly closed yet (probably because of write failure during initialization).

@grandinj
Copy link
Contributor

grandinj commented Jan 9, 2019

Why MVStore.stopBackgroundThread() is entered with different locked objects? Database+Session+other, Engine+Database+other, Session+Engine.

I guess because it is called from different paths, and each path has it's own locking regime.

However, I don't see how background writer thread may prevent database shutdown process. I checked with debug print that previous connection is closed and background writer thread is still alive before the failure. It looks like only connection is closed, but database is not properly closed yet (probably because of write failure during initialization).

Possibly the problem is then that the background writer thread should either not be started until later in init, or should be shut down better if we get a write failure during init

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

I tried to add a separate flag to prevent its startup if database in already in shutdown process or after it, but it did not help. Also this thread has nothing to do with the storage. There is a combination of the following factors:

  1. The single connection is already closed.
  2. File system is still locked.
  3. Background writer thread is still alive.
  4. Background writer thread in going to catch an exception on the next writing attempt.

Due to (2) and (3) I think that database is not really closed. After (4) database is closed completely by exception handler.

@grandinj
Copy link
Contributor

grandinj commented Jan 9, 2019

So the problem is that we are not properly closing the database when the last connection goes away, and we end up closing the database as a side effect of the exception handler when the the background writer tries to write to the database?

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

Something like it. However, database is already deregistered from the Engine, and it was deregistered from the finally block in Database.close(boolean)method.

But with some additional debug print I found that this method did nothing in the large try block, because Database.closing was set to true before it. So there was an early return.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

And closing was set by Database.shutdownImmediately().

@grandinj
Copy link
Contributor

grandinj commented Jan 9, 2019

Database.shutdownImmediately should have called Database.closeFiles and shut down the mvstore

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

MVStore is already closed somehow, so MVTableEngine.closeImmediately() does nothing.

@grandinj
Copy link
Contributor

grandinj commented Jan 9, 2019

the bulk of MVStore's close logic is in closeStore.

Possibly what we have here is some kind of race condition, where the the "closed" flag is set because the close process is happening on thread A, but then thread B comes along, calls close(), does a short-circuit return, and then and tries to re-open the DB but the close process is still on-going.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

It looks like this issue disappears if both MVStore.closeStore(boolean) and MVStore.isClosed() are synchronized.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

Maybe we need a some tri-state close flag and delayed return from isClosed() when store is closing.

@grandinj
Copy link
Contributor

grandinj commented Jan 9, 2019

Sounds reasonable

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

Actually in looks like 4 states are needed, one additional state for termination of background writer.

Also I see an unlikely, but possible race in background writer thread startup code if simple volatile int will be used. I guess it's better to make code fully reliable with AtomicInt or something like it.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

No, AtomicInt is not required, but small synchronized blocks are necessary for background writer initialization / termination.

@katzyn
Copy link
Contributor Author

katzyn commented Jan 9, 2019

It's possible to start two background writer threads due to lack of proper synchronization.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants