Corrupted database (again) with h2-1.4.199

[Silvio]

Today we experienced another database corruption. The difference with earlier cases is that this time it happened during normal production use of the system while the previous cases seemed to occur during nightly system restarts.

The system is a Ubuntu 19.04 server running a singular standalone Java server application with OpenJDK 12. The server application accesses a couple of hundred H2 file-based (MVStore) databases in embedded mode. The connection pool takes care of limiting the number of concurrently open connections to a maximum of 99.

Since we have been running this setup about 20-fold during multiple years without ever experiencing this until we upgraded from h2-1.4.196 to h2-1.4.199 I am convinced something has changed for the worse between these versions.

This is the stack trace:

2019-05-17 15:35:43 database: flush

org.h2.message.DbException: General error: "java.lang.IllegalStateException: File corrupted in chunk 16664, expected page length 4..1536, got 1768842341 [1.4.199/6]" [50000-199]

at org.h2.message.DbException.get(DbException.java:194)

at org.h2.message.DbException.convert(DbException.java:347)

at org.h2.mvstore.db.MVTableEngine$1.uncaughtException(MVTableEngine.java:90)

at org.h2.mvstore.MVStore.handleException(MVStore.java:2787)

at org.h2.mvstore.MVStore.panic(MVStore.java:441)

at org.h2.mvstore.MVStore.<init>(MVStore.java:404)

at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3343)

at org.h2.mvstore.db.MVTableEngine$Store.open(MVTableEngine.java:162)

at org.h2.mvstore.db.MVTableEngine.init(MVTableEngine.java:95)

at org.h2.engine.Database.getPageStore(Database.java:2739)

at org.h2.engine.Database.open(Database.java:769)

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:201)

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:336)

at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:169)

at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:148)

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)

[Andrei Tokar]

Your stack trace indicates that database is starting, so it is not obvious that it happened "during normal production use of the system". It was shut down (possibly abruptly?) before this.

It was more than enough changes, of course, between 1.4.196 and 1.4.199, and many of them are targeted at providing a better throughput for your 99 concurrent connections.

Unfortunately, it is extremely hard to find the issue without reliably reproducible test case, but if you have one...

[Silvio]

Yes, databases are shutdown and reopened constantly since the connection pool will only keep unused connections around for a short period of time before closing them. As a result databases are closed by H2 automatically once the last connection is closed. This particular type of issue appears to result in database corruptions that usually do not show up until the database is closed and reopened.

I realize that changes are necessary and appreciate the performance improvements which are more than noticeable. I am merely trying to find out if some things may have changed that make my usage pattern (accessing many embedded databases from the same process with a connection pool that opens/closes connections at a quite high rate) possibly more fragile. If so, I would be more than willing to make adjustments or do specific testing.

As a software developer I understand how hard it can be to find issues when they can not be reproduced predictably. The problem occurs intermittently so might be related to specific timing or synchronization scenarios.

[Silvio]

Unfortunately we currently have another case of database corruption. The exception stack trace is identical to the one I posted above. What strikes me is that the messages reads "database: flush" and subsequently the stack trace seems to imply the database is being opened. That sounds contradictory to me.

The only common denominator is that all databases are MVStore ones. Connections are not shared among threads but multiple threads do access the same database via separate connections at the same time. Could something be off there? We do exactly the same thing with the PageStore databases we have left in operations but none of these have gone bad during these last weeks running on 199.

I am considering reverting to version 196. Is that even an option after databases have been written (and possibly even created) using 199? 

[Silvio]

Sorry for spamming but I am just thinking out loud here:

Suppose we do leak connections across threads and multiple writes and/or closes are performed on the same connections. Could that cause database corruption? I know it is a hard call but does it sound likely or even possible that changes since 196 might render H2 more sensitive for such scenario's?

More info on this would be very helpful for pinpointing any wrongdoing on our side.

[Noel Grandin]

What does one of your database URLs look like?

Are you perhaps call Thread.interrupt somewhere?

If so, that would close the database abruptly and force it to be re-opened on the next connection attempt.

Doing that enough times is likely to cause corruption, because all kinds of stuff could be in-flight and unwritten to
actual physical storage.

That is currently our weak link - we are not sufficiently tolerant of systems with large write queues that re-order
stuff before it hits disk.

[Silvio]

The database URLs currently look like:

jdbc:h2:/path/to/file;IGNORECASE=TRUE;MVCC=TRUE;LOCK_TIMEOUT=10000

I have experimented with different FILE_LOCK settings but since the databases are accessed from one single process this is unlikely to have any influence. I could probably do without MVCC=TRUE for 199 but was not sure.

We do not call Thread.interrupt at all.

All database-actions are performed as fetch-connection/perform/release-connection cycles (only in auto-commit mode, otherwise the same connection is reused). Sometimes a thread may call nested actions that have their own fetch/perform/release cycle which results in multiple connections being used inside the same thread (again in auto-commit mode only). An example would be using one connection to cycle through a result-set and using another one to do selects/updates/inserts for each record fetched.

[Noel Grandin]

On 2019/05/21 4:21 PM, Silvio wrote:
> The database URLs currently look like:
>

None of that sounds problematic. You might be able to work around this issue simply by telling your pool to keep
connections alive for longer, which will reduce the number of startup/shutdown cycles each database file has to perform.

[Silvio]

Additionally, large write queues are very common in our system. At least one of the most recent corruptions occurred when a user performed an action that caused a new table to be created and ~200K records to be inserted into it (using separate connect/insert/disconnect cycles, pooled of course).

[Silvio]

Thank you, that is an excellent suggestion. The times are very short now but there is no pressing reason for that other than hoping it would reduce resource consumption. I will change that ASAP.

[Silvio]

Yesterday evening at about 20:00 another database on one of our servers got corrupted (at least that is when errors started appearing in the logging). There was limited server load at the time. In this case it was a database of about 850Mb.

To determine our options I would like to raise my earlier question again: is there a binary difference in MVStore/PageStore formats between version 199 and 196? In other words: would it be safe to revert to 196 without doing dump/recreate cycles for all our databases?

The current rate of failures is seriously hurting customer confidence so we may have to revert to 196 for the short term and do more testing on non-critical installations with the newer versions.

[Noel Grandin]

On 2019/05/22 11:21 AM, Silvio wrote:
> To determine our options I would like to raise my earlier question again: is there a binary difference in
> MVStore/PageStore formats between version 199 and 196? In other words: would it be safe to revert to 196 without doing
> dump/recreate cycles for all our databases?
>

No, you'll need to do dump/restore cycles.

PageStore hasn't changed in a while, MVStore has had some small binary changes that make rolling back tricky sometimes,
but the more important thing is that some of the fixes to the MetaTable stuff might bite you.

[Silvio]

Thanks. I will take that into account.

[Silvio]

Today I discovered something very interesting. I took a corrupted database that 199 tripped over and tried running the recovery tool. This resulted in a similar exception our application logged at the time the database got corrupted:

jambo@jambo8:~$ java -cp h2-1.4.199.jar org.h2.tools.Recover

Exception in thread "main" java.lang.IllegalStateException: Reading from nio:/home/jambo/database.mv.db failed; file length 1127067648 read length 4096 at 1152263673 [1.4.199/1]

at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:883)

at org.h2.mvstore.DataUtils.readFully(DataUtils.java:420)

at org.h2.mvstore.FileStore.readFully(FileStore.java:98)

at org.h2.mvstore.MVStore.readBufferForPage(MVStore.java:1048)

at org.h2.mvstore.MVStore.readPage(MVStore.java:2186)

at org.h2.mvstore.MVMap.readPage(MVMap.java:554)

at org.h2.mvstore.Page$NonLeaf.getChildPage(Page.java:1086)

at org.h2.mvstore.Cursor.hasNext(Cursor.java:53)

at org.h2.mvstore.MVStore.readStoreHeader(MVStore.java:793)

at org.h2.mvstore.MVStore.<init>(MVStore.java:401)

at org.h2.mvstore.MVStore$Builder.open(MVStore.java:3343)

at org.h2.mvstore.MVStoreTool.info(MVStoreTool.java:347)

at org.h2.tools.Recover.process(Recover.java:344)

at org.h2.tools.Recover.runTool(Recover.java:195)

at org.h2.tools.Recover.main(Recover.java:158)

Caused by: java.io.EOFException

at org.h2.mvstore.DataUtils.readFully(DataUtils.java:408)

... 13 more

So I decided to try the same thing using 196:

jambo@jambo8:~$ java -cp h2-1.4.196.jar org.h2.tools.Recover

what gives? NO ERROR! Version 196 succesfully created a SQL script and I was able to create a new database from it using:

jambo@jambo8:~$ java -cp h2*.jar org.h2.tools.RunScript -url jdbc:h2:./database -user sa -script database.h2.sql

I have yet to determine if there is anything missing from this recovered database, which will not be easy. But from where I stand 199 trips over a database file that 196 can process. Of course I understand that this does not mean all would be fine using the database in 196 but does this make any sense to you? Could it be that 199 is more likely to throw an exception on the same database? Or could this just be an example of 196 functioning improperly on a database that has been written to by 199 without throwing an exception at all?

I will start evaluating the recovered database to see if it is a complete recovery and report back here. In the meantime any insights into this matter would be very appreciated.

[Silvio]

My first inspection of the recovered database reveals that the database seems to be fully intact. I compared it with a backup from the day before the corruption happened. The exact same set of tables is there and the record counts in corresponding tables is the same or the differences are small enough to be explained by the time difference. I can not say anything about the contents of individual cells but all queries I did returned expected results.

So this makes me come back to my previous question: does it make sense that 199 considers a database corrupt when 196 does not? And if so: which of both is right?

[Silvio]

For what it's worth: using 196 directly on the original corrupted database (so not to run the recovery tool but with our application) shows no signs of the database being corrupted. I know this does not mean anything but nothing I have tried showed any sign of errors or malfunction. Consider me baffled.

[Andrei Tokar]

Are there any chance, you can share original corrupted file?

[Silvio]

Unfortunately not. The data belongs to a customer. I would be happy to do any kind of testing for you though.

[Andrei Tokar]

Too bad 8-(

I was thinking about running recovery tool under debugger to see what's going on.

BTW, error from recovery is different from the one database it throwing. Recovery is saying that file was kind of illegally truncated and is too short now, while database is complaining about corrupted page.

But it is really weird, since 1.4.196 is fine in both cases.

What you can do though, so we do not chase black cat in a dark room, when it is not there, is to build from current git master branch http://h2database.com/html/build.html and see if problem is still there.

[Silvio]

I just tried to build but I am running openjdk13 (openjdk12 on the servers) and the build fails (package com.sun.javadoc does not exist). I used to be able to build H2 earlier when I was running openjdk11.

I will try building with an older JDK tomorrow. Any preference for one?

[Silvio]

I managed to build h2 with openjdk8. The recover tool fails in the same way with that version as it does with current 199. I tried with 198 and that fails also. Then I tried 197 and that succeeds, just like 196.

[Andrei Tokar]

Hi Silvio,

I just merged into master presumable fix for your issue, but I can not really verify that it works.

If you can rebuild h2 from master branch again and try to open that corrupted file...

[Silvio]

Hi Andrei,

Thank you again for delving into this. I built from master branch and first ran the recover tool. You are definitely on to something here because where 199 trips over the database with an exception during the generation of database.mv.txt master generates a similarly sized database.mv.txt as 197 does, somewhere around 443Mb (database.mv.db is 1.1Gb) without exceptions. But where 197 subsequently generates a 2.5Gb database.mv.sql master generates one of 750 bytes containing:

***** START (not part of file)

-- MVStore

CREATE ALIAS IF NOT EXISTS READ_BLOB FOR "org.h2.tools.Recover.readBlob";

CREATE ALIAS IF NOT EXISTS READ_CLOB FOR "org.h2.tools.Recover.readClob";

CREATE ALIAS IF NOT EXISTS READ_BLOB_DB FOR "org.h2.tools.Recover.readBlobDb";

CREATE ALIAS IF NOT EXISTS READ_CLOB_DB FOR "org.h2.tools.Recover.readClobDb";

CREATE ALIAS IF NOT EXISTS READ_BLOB_MAP FOR "org.h2.tools.Recover.readBlobMap";

CREATE ALIAS IF NOT EXISTS READ_CLOB_MAP FOR "org.h2.tools.Recover.readClobMap";

-- Meta

-- Tables

---- Schema SET ----

---- Table Data ----

---- Schema ----

DROP ALIAS READ_BLOB;

DROP ALIAS READ_CLOB;

DROP ALIAS READ_BLOB_DB;

DROP ALIAS READ_CLOB_DB;

DROP ALIAS READ_BLOB_MAP;

DROP ALIAS READ_CLOB_MAP;

DROP TABLE IF EXISTS INFORMATION_SCHEMA.LOB_BLOCKS;

***** END (not part of file)

I then tried to open the database with the H2 console and that fails with this message:

General error: "java.lang.IllegalStateException: Unsupported type 17 [1.4.199/3]" [50000-199] HY000/50000 (Help)

[Silvio]

Hi Andrei,

Did you get anywhere from here using my feedback? Or do you need more information? I would be very interested to hear more about this problem.

We just had a very peculiar database corruption: the corrupted database (~5Mb) can be accessed from 199 but it appears to be as good as empty. Using 199 to dump the database to an SQL script results in a script with a single CREATE TABLE statement. I used 197 to dump it and got an SQL file of ~17Mb. Importing that got me a working database again, both with 197 and 199.

As you can probably sense I am getting a bit nervous about all this. I am still considering reverting to 196 but since that would require me to do a full dump-with-199/import-with-196 cycle for all my databases (somewhere around 10K by now) this would be quite an endeavor.

[Silvio]

It is getting monotonic but we had another database corruption. It happened on the same database I have been doing these tests on but since this is one of the bigger databases we have that may not be remarkable.

Today we used a different recovery approach: instead of restoring a backup (which lags behind up to 24 hours) we did a recover-with-196/restore-with-199 cycle. Luckily that worked.

We can no longer risk any more downtime or worse: losing more client data so we have decided to revert to 196 for now. Nonetheless will I be working on this and if I can do anything to help resolve this issue I will be more than happy to.