Index corruption bug

[Andrew]

We have recently encountered an issue where updateRow() fails due to an apparently corrupt H2 index.  This particular index is on a varchar column that can contain relatively large (1000-2000 characters is not uncommon) values.  We have reproduced this on both 1.3.163 and 1.3.165.  The issue appears to depend entirely upon the nature of the data stored in the indexed table -- in one deployment with 3000+ rows we have not experienced any corruption, while in another deployment with approximately 1300 rows a corrupted index occurred.

Depending upon the data inserted into the table, and the order in which rows are updated, we have seen two different exceptions:

1.
Exception in thread "main" org.h2.jdbc.JdbcSQLException: Row not found when trying to delete from index "PUBLIC.IDX: ( /* key:226 */ 226, '{""operation"":""ADD"",""keys"":[""21216384"", ... ""21299408""]}', FALSE)"; SQL statement:
UPDATE "PUBLIC"."T" SET "ID"=? ,"S"=? ,"B"=?  WHERE "ID"=? [90112-163]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)
    at org.h2.message.DbException.get(DbException.java:169)
    at org.h2.message.DbException.get(DbException.java:146)
    at org.h2.index.PageBtreeLeaf.remove(PageBtreeLeaf.java:224)
    at org.h2.index.PageBtreeNode.remove(PageBtreeNode.java:324)
    ...
    at org.h2.index.PageBtreeNode.remove(PageBtreeNode.java:324)
    at org.h2.index.PageBtreeIndex.remove(PageBtreeIndex.java:241)
    at org.h2.table.RegularTable.removeRow(RegularTable.java:361)
    at org.h2.table.Table.updateRows(Table.java:430)
    at org.h2.command.dml.Update.update(Update.java:128)
    at org.h2.command.CommandContainer.update(CommandContainer.java:73)
    at org.h2.command.Command.executeUpdate(Command.java:226)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:143)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:129)
    at org.h2.result.UpdatableRow.updateRow(UpdatableRow.java:285)
    at org.h2.jdbc.JdbcResultSet.updateRow(JdbcResultSet.java:2763)
    at Reproducer.main(Reproducer.java:55)

2.
Exception in thread "main" org.h2.jdbc.JdbcSQLException: General error: "java.lang.ArrayIndexOutOfBoundsException: 2"; SQL statement:
UPDATE "PUBLIC"."T" SET "ID"=? ,"S"=? ,"B"=?  WHERE "ID"=? [50000-163]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)
    at org.h2.message.DbException.get(DbException.java:158)
    at org.h2.message.DbException.convert(DbException.java:281)
    at org.h2.table.RegularTable.removeRow(RegularTable.java:379)
    at org.h2.table.Table.updateRows(Table.java:430)
    at org.h2.command.dml.Update.update(Update.java:128)
    at org.h2.command.CommandContainer.update(CommandContainer.java:73)
    at org.h2.command.Command.executeUpdate(Command.java:226)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:143)
    at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:129)
    at org.h2.result.UpdatableRow.updateRow(UpdatableRow.java:285)
    at org.h2.jdbc.JdbcResultSet.updateRow(JdbcResultSet.java:2763)
    at Reproducer.main(Reproducer.java:54)
Caused by: java.lang.ArrayIndexOutOfBoundsException: 2
    at org.h2.index.PageBtree.getRow(PageBtree.java:172)
    at org.h2.index.PageBtreeLeaf.remove(PageBtreeLeaf.java:222)
    at org.h2.index.PageBtreeNode.remove(PageBtreeNode.java:324)
    ...
    at org.h2.index.PageBtreeNode.remove(PageBtreeNode.java:324)
    at org.h2.index.PageBtreeIndex.remove(PageBtreeIndex.java:241)
    at org.h2.table.RegularTable.removeRow(RegularTable.java:361)
    ... 9 more

I've attached a zip file containing the Java code for a standalone, minimal reproducer application along with two data files, one for each type of exception seen.  I suspect some sort of unfortunate hash collision could be happening.  Please let me know if any additional information is needed to track this issue down.

thanks,
Andrew Olson

[Thomas Mueller]

Hi,

Thanks a lot for the great test case! I can reproduce the problem, it
will be fixed in the next release.

Regards,
Thomas

> --
> You received this message because you are subscribed to the Google Groups
> "H2 Database" group.
> To view this discussion on the web visit
> https://groups.google.com/d/msg/h2-database/-/GIpAUvXRdPkJ.
> To post to this group, send email to h2-da...@googlegroups.com.
> To unsubscribe from this group, send email to
> h2-database...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/h2-database?hl=en.

[Andrew]

Thanks, Thomas.

- Andrew

> h2-database+unsubscribe@googlegroups.com.

[wburzyns]

This bug is a bit scary as I also have indices on not-so-small varchar
columns.
Thomas, can we know when do you plan to release the next H2 version?

Thanks,
wburzyns

On Apr 3, 9:28 pm, Thomas Mueller <thomas.tom.muel...@gmail.com>
wrote:

[Thomas Mueller]

Hi,

> This bug is a bit scary as I also have indices on not-so-small varchar
> columns.

Yes, it is scary.

> Thomas, can we know when do you plan to release the next H2 version?

As soon as this bug is fixed, I hope this weekend.

Regards,
Thomas

[Thomas Mueller]

Hi,

I have some news on this. The main problem is a bug in the b-tree
index code that speeds up updates. There is a 'kill switch' for this
feature, you can disable it if you append ";optimize_update=false" to
the database URL. The test does no longer fail if I did this. There is
another problem I want to solve as well: when running this test case,
the b-tree pages are split at the wrong position, so that the database
is much larger than needed.

Both problems only occur when using an index on variable size data, if
the data to be indexed is very big (larger than 1 KB).

I will fix both problems this weekend and will release a new version.
But first I want to create a better test case to make sure this will
not break in the future.

Regards,
Thomas

[Andrew]

It looks like this bug has been fixed in version 1.3.166 [1].

Thomas, do you anticipate any issues with reading/migrating (non-corrupt) indexes previously created by an older version of H2?  Are any special upgrade steps required to start using the latest code?

thanks,
Andrew

[1] http://www.h2database.com/html/changelog.html

[Thomas Mueller]

Hi,

> do you anticipate any issues with reading/migrating (non-corrupt)
> indexes previously created by an older version of H2?  Are any special
> upgrade steps required to start using the latest code?

From what I know, if you got the problem, then you would need to
export and re-import the data (using the SCRIPT TO / RUNSCRIPT
statements or Script / RunScript tools).

I'm not sure that it is possible to get indexes corrupt without this
being detected. I think typically you would notice the problem. But it
is probably a good idea to re-import the data if you have such wide
indexes.

Regards,
Thomas

[Sandeep Tamhankar]

Not for me, unfortunately. Running 1.3.166, embedded in my app, I got the following stack trace today:

05-02 06:41:42 jdbc[8]: exception

org.h2.jdbc.JdbcSQLException: Row not found when trying to delete from index "PUBLIC.I_JSTEP_FINISH_TIME: ( /* key:3339153 */ 3339153, 0, 'Windows', TIMESTAMP '2009-03-08 00:30:00.734', 1236472200734, NULL, 'admin', TIMESTAMP '2009-03-08 02:11:13.281', 1236478273281, 'project: Commander', 'none', 'none', NULL, NULL, NULL, NULL, FALSE, NULL, FALSE, NULL, 'true', NULL, NULL, NULL, TRUE, NULL, NULL, NULL, 'failProcedure', 0, 0, TIMESTAMP '2009-03-08 02:10:34.844', 1236478234844, 0, NULL, NULL, NULL, 0, 'Windows.3339153.log', 'error', TRUE, 0, 'Master', NULL, 'procedure', 0, 0, NULL, 0, TIMESTAMP '2009-03-08 00:31:50.936', 1236472310936, NULL, 0, TIMESTAMP '2009-03-08 00:31:52.451', 1236472312451, 0, 'completed', 'Master-OnePlatform', 'Commander', 0, NULL, NULL, FALSE, NULL, NULL, 0, 2583807, 5932765, 2583808, NULL, NULL, NULL, NULL, NULL, 151908, 3339144, NULL, NULL, NULL)"; SQL statement:

/* update com.electriccloud.commander.domain.JobStepImpl */ update ec_job_step set version=?, procedure_id=?, procedure_step_id=? where id=? and version=? [90112-166]

at org.h2.message.DbException.getJdbcSQLException(DbException.java:329)

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

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

at org.h2.index.PageBtreeLeaf.remove(PageBtreeLeaf.java:225)

at org.h2.index.PageBtreeNode.remove(PageBtreeNode.java:324)

at org.h2.index.PageBtreeNode.remove(PageBtreeNode.java:324)

at org.h2.index.PageBtreeNode.remove(PageBtreeNode.java:324)

at org.h2.index.PageBtreeIndex.remove(PageBtreeIndex.java:241)

at org.h2.index.MultiVersionIndex.remove(MultiVersionIndex.java:170)

at org.h2.table.RegularTable.removeRow(RegularTable.java:361)

at org.h2.table.Table.updateRows(Table.java:430)

at org.h2.command.dml.Update.update(Update.java:143)

at org.h2.command.CommandContainer.update(CommandContainer.java:73)

at org.h2.command.Command.executeUpdate(Command.java:226)

at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:143)

at org.h2.jdbc.JdbcPreparedStatement.executeBatch(JdbcPreparedStatement.java:1092)

at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:473)

at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)

at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)

at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:114)

at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:109)

at org.hibernate.jdbc.AbstractBatcher.prepareBatchStatement(AbstractBatcher.java:244)

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2582)

at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2535)

at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2862)

at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:113)

at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:282)

at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:274)

at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:192)

at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:327)

at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51)

at com.electriccloud.hibernate3.HibernateEventListenerImpl.onFlush(HibernateEventListenerImpl.java:80)

at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216)

at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:383)

at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:133)

at com.electriccloud.hibernate3.HibernateTransactionHelper.commit(HibernateTransactionHelper.java:192)

at com.electriccloud.transaction.AbstractTransactionHelper.commitAndBegin(AbstractTransactionHelper.java:97)

at com.electriccloud.transaction.AbstractTransactionHelper.commitPeriodically(AbstractTransactionHelper.java:121)

at sun.reflect.GeneratedMethodAccessor1234.invoke(Unknown Source)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:601)

My jdbc url: jdbc:h2:builtin/foo;MVCC=TRUE;CACHE_SIZE=128000

Not sure this is important, but my application was churning for about 36 hours importing data (in our own xml format) before it failed like this. The db file was about 19GB. I'm running jdk 1.7.0_03. I looked through the schema for any varchar columns > 1k, and it seems we do have one column that is a varchar(4000). I have to search the data to see if we actually supply a value above 1k for that column.

-Sandeep

[Thomas Mueller]

Hi,

Not for me, unfortunately. Running 1.3.166, embedded in my app

Could you check that the database file was created with version 1.3.166? To do this, run the statement

SELECT * FROM INFORMATION_SCHEMA.SETTINGS 

WHERE NAME='CREATE_BUILD'

The result should be 166. If it is, could you send me a reproducible test case if that's possible?

Regards,

Thomas

[Sandeep Tamhankar]

It's definitely a 1.3.166 db. My application starts with a clean h2 db and is loading the db from an xml file (exported from our application previously). I was hoping the stack trace I reported would be enough info for you because it took about 36 hours and a 19GB database before the failure occurred.

However, just yesterday a colleague ran into a similar error while importing an xml file where his failure occurred after about an hour. This leads me to believe there's something about the structure of our data that leads to this case. I'll spend some time today trying to shrink the failure scenario to as small amount of data/time as possible and get back to you.

-Sandeep

[Sandeep Tamhankar]

Ok, I just filed issue 398 and included a link to the gzipped trace file there. Good luck!

-Sandeep

[Sandeep Tamhankar]

I submitted issue 398 about 3-4 days ago with a link to a trace file showing the issue. Have you had a chance to look at it yet?

Some background: this trace file encompasses the following events in our application:

* Application startup, creates schema (via Hibernate), inserts some data.

* Import operation of data from xml file. This results in most/all tables being cleared, then data imported. Every 50 or so actions (which I'd guess are inserts) we commit a transaction.

Thanks!

-Sandeep

On Tuesday, May 8, 2012 11:43:21 PM UTC-7, Thomas Mueller wrote:

[Thomas Mueller]

Hi,

You sent me a 1.29 GB trace.db file. I'm sorry, but I don't have the
time to analyze it.

I suggest to check the pages
http://h2database.com/html/faq.html#support ,
http://h2database.com/html/build.html#support - specially "For bug
reports, please provide a short, self contained, correct (compilable),
example of the problem." - and http://sscce.org/

Regards,
Thomas

> --
> You received this message because you are subscribed to the Google Groups
> "H2 Database" group.
> To view this discussion on the web visit

> https://groups.google.com/d/msg/h2-database/-/_sY4Yzl51agJ.