Exception when opening DB after forced shutdown (1.3.176)

433 views
Skip to first unread message

too

unread,
May 20, 2014, 9:16:03 AM5/20/14
to h2-da...@googlegroups.com
Hi,
Sometimes when our application is shut down forcibly it is unable to start again with exceptions below. It does not appear that transaction is in progress at the time of shutdown but I can not be sure. I was unable to create test case but our application reproduces this quite consistently (it's very rare that it starts after being terminated). 
I have attached debug trace file for failed start - not for the shutdown. I tried INFO logging for shutdown (breaking the db) but nothing seemed interesting there, just bunch of selects. Also no error is logged during shutdown or startup.

Environment details are
  • H2 - 1.3.176
  • Java Runtime     - Java(TM) SE Runtime Environment (1.7.0_17-b02, 32b) on Java HotSpot(TM) Client VM (23.7-b01, mixed mode)
  • Operating System - Windows 7 (64b, Service Pack 1, version 6.1) 
  • connection URL - jdbc:h2:./dbfile;IFEXISTS=TRUE

NullPointerException - this is what usually happens
org.h2.jdbc.JdbcSQLException: General error: "java.lang.NullPointerException" [50000-176]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:344) ~[h2.jar:1.3.176]
at org.h2.message.DbException.get(DbException.java:167) ~[h2.jar:1.3.176]
at org.h2.message.DbException.convert(DbException.java:294) ~[h2.jar:1.3.176]
at org.h2.engine.Database.openDatabase(Database.java:291) ~[h2.jar:1.3.176]
at org.h2.engine.Database.<init>(Database.java:254) ~[h2.jar:1.3.176]
at org.h2.engine.Engine.openSession(Engine.java:57) ~[h2.jar:1.3.176]
at org.h2.engine.Engine.openSession(Engine.java:164) ~[h2.jar:1.3.176]
at org.h2.engine.Engine.createSessionAndValidate(Engine.java:142) ~[h2.jar:1.3.176]
at org.h2.engine.Engine.createSession(Engine.java:125) ~[h2.jar:1.3.176]
at org.h2.engine.Engine.createSession(Engine.java:27) ~[h2.jar:1.3.176]
at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:331) ~[h2.jar:1.3.176]
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:107) ~[h2.jar:1.3.176]
at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:91) ~[h2.jar:1.3.176]
at org.h2.Driver.connect(Driver.java:74) ~[h2.jar:1.3.176]
at java.sql.DriverManager.getConnection(DriverManager.java:579) ~[na:1.7.0_17]
at java.sql.DriverManager.getConnection(DriverManager.java:221) ~[na:1.7.0_17]
at ...
... 12 common frames omitted
Caused by: java.lang.NullPointerException: null
at org.h2.store.PageStore.removeMeta(PageStore.java:1642) ~[h2.jar:1.3.176]
at org.h2.store.PageStore.redo(PageStore.java:1565) ~[h2.jar:1.3.176]
at org.h2.store.PageStore.redoDelete(PageStore.java:1550) ~[h2.jar:1.3.176]
at org.h2.store.PageLog.recover(PageLog.java:347) ~[h2.jar:1.3.176]
at org.h2.store.PageStore.recover(PageStore.java:1407) ~[h2.jar:1.3.176]
at org.h2.store.PageStore.openExisting(PageStore.java:368) ~[h2.jar:1.3.176]
at org.h2.store.PageStore.open(PageStore.java:289) ~[h2.jar:1.3.176]
at org.h2.engine.Database.getPageStore(Database.java:2366) ~[h2.jar:1.3.176]
at org.h2.engine.Database.open(Database.java:657) ~[h2.jar:1.3.176]
at org.h2.engine.Database.openDatabase(Database.java:260) ~[h2.jar:1.3.176]
... 25 common frames omitted

ArrayIndexOutOfBoundsException - I got this one only once
Caused by: org.h2.jdbc.JdbcSQLException: General error: "java.lang.ArrayIndexOutOfBoundsException: 44" [50000-176]
        at org.h2.message.DbException.getJdbcSQLException(DbException.java:344) ~[h2.jar:1.3.176]
        at org.h2.message.DbException.get(DbException.java:167) ~[h2.jar:1.3.176]
        at org.h2.message.DbException.convert(DbException.java:294) ~[h2.jar:1.3.176]
        at org.h2.engine.Database.openDatabase(Database.java:291) ~[h2.jar:1.3.176]
        at org.h2.engine.Database.<init>(Database.java:254) ~[h2.jar:1.3.176]
        at org.h2.engine.Engine.openSession(Engine.java:57) ~[h2.jar:1.3.176]
        at org.h2.engine.Engine.openSession(Engine.java:164) ~[h2.jar:1.3.176]
        at org.h2.engine.Engine.createSessionAndValidate(Engine.java:142) ~[h2.jar:1.3.176]
        at org.h2.engine.Engine.createSession(Engine.java:125) ~[h2.jar:1.3.176]
        at org.h2.engine.Engine.createSession(Engine.java:27) ~[h2.jar:1.3.176]
        at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:331) ~[h2.jar:1.3.176]
        at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:107) ~[h2.jar:1.3.176]
        at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:91) ~[h2.jar:1.3.176]
        at org.h2.Driver.connect(Driver.java:74) ~[h2.jar:1.3.176]
        at java.sql.DriverManager.getConnection(DriverManager.java:579) ~[na:1.7.0_17]
        at java.sql.DriverManager.getConnection(DriverManager.java:221) ~[na:1.7.0_17]
        at com.stsjava.fieldit.dbdrv.dbjdbc.DbJdbcDataToolkit.createConnection(DbJdbcDataToolkit.java:490) ~[fieldit.jar:na]
        ... 12 common frames omitted
Caused by: java.lang.ArrayIndexOutOfBoundsException: 44
        at org.h2.index.PageDataLeaf.getRowAt(PageDataLeaf.java:333) ~[h2.jar:1.3.176]
        at org.h2.index.PageDataLeaf.getRowWithKey(PageDataLeaf.java:456) ~[h2.jar:1.3.176]
        at org.h2.index.PageDataNode.getRowWithKey(PageDataNode.java:281) ~[h2.jar:1.3.176]
        at org.h2.index.PageDataIndex.getRowWithKey(PageDataIndex.java:427) ~[h2.jar:1.3.176]
        at org.h2.store.PageStore.redoDelete(PageStore.java:1549) ~[h2.jar:1.3.176]
        at org.h2.store.PageLog.recover(PageLog.java:347) ~[h2.jar:1.3.176]
        at org.h2.store.PageStore.recover(PageStore.java:1407) ~[h2.jar:1.3.176]
        at org.h2.store.PageStore.openExisting(PageStore.java:368) ~[h2.jar:1.3.176]
        at org.h2.store.PageStore.open(PageStore.java:289) ~[h2.jar:1.3.176]
        at org.h2.engine.Database.getPageStore(Database.java:2366) ~[h2.jar:1.3.176]
        at org.h2.engine.Database.open(Database.java:657) ~[h2.jar:1.3.176]
        at org.h2.engine.Database.openDatabase(Database.java:260) ~[h2.jar:1.3.176]
        ... 25 common frames omitted

thanks
Tono 
rtarm142.trace.db.7z

Thomas Mueller

unread,
May 22, 2014, 11:46:55 AM5/22/14
to h2-da...@googlegroups.com
Hi, 

I would need a reproducible test case. 

Regards, Thomas 
--
You received this message because you are subscribed to the Google Groups "H2 Database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to h2-database...@googlegroups.com.
To post to this group, send email to h2-da...@googlegroups.com.
Visit this group at http://groups.google.com/group/h2-database.
For more options, visit https://groups.google.com/d/optout.

too

unread,
May 22, 2014, 11:47:11 AM5/22/14
to h2-da...@googlegroups.com
I have experimented with this a little and here are few notes
  • lock file remains in place - this is consistent with shutdown hooks not being executed during JVM abort
  • size of DB file remains intact during runtime but during process termination the size rises by approximately 50MB - which contradicts previous point and it seems there is something executed during abort
  • I can replicate problem with 100% success rate using our app but I fail to create test app to replicate the problem (still have a few ideas to try)
  • I can replicate the problem with older 1.3.x releases as well as with latest 1.4.x release (with MV_STORE=FALSE)
  • even though I do not think that there are transactions in progress at the time of termination it is possible there are open cursors or something similar - read-related
I can avoid this problem by running H2 in server mode but that is not what I want. 

Tono

too

unread,
May 27, 2014, 7:37:14 AM5/27/14
to h2-da...@googlegroups.com
Even though I can reproduce this with our app I fail to create separate test case to reproduce the problem (i.e. to break the DB). What I can do is send you database that H2 fails to open. Perhaps it is not really bug during close but not robust enough recovery during startup. Zipped DB has 10MB and I can share it for you privately if you think that can help

thanks
Tono

Thomas Mueller

unread,
Jun 2, 2014, 12:04:03 PM6/2/14
to h2-da...@googlegroups.com
Hi,

I could analyze it now. The problem seems to be that creating a temporary table is not committed, and then the temporary table is deleted in another session. I have a fix / workaround for that, but so far no test case. Please tell me if you have a reproducible test case.

Regards,
Thomas

--

too

unread,
Jun 3, 2014, 4:58:40 AM6/3/14
to h2-da...@googlegroups.com
Hello,
I can test the fix for you easily, all I need is h2 jar with fix. 

Regarding the test I tried all I could think of. Our app is fairly large (15MB jar of classes with lots of framework-ish stuff happening in the background) so it is difficult to point out the scenario. Tried INFO logging to re-execute the same set of queries but that has not replicated the problem. I am also pretty sure we do not create any temporary tables explicitly (also searched code-base for "create memory table").

Can you point me in some direction as what to look for? I mean what would you expect to be happening to create the table? Does H2 create temp tables implicitly? All we do to trigger the problem are select queries (based on the info log I had).

thanks
Tono
To unsubscribe from this group and stop receiving emails from it, send an email to h2-database+unsubscribe@googlegroups.com.

Thomas Mueller

unread,
Jun 4, 2014, 2:52:08 PM6/4/14
to H2 Google Group
Hi,

The latest build is available at: http://h2database.com/html/build.html#automated

> Can you point me in some direction as what to look for?

If you don't create temporary tables, then most likely the problem is large result sets, as in some cases this will implicitly create temporary tables. I found out this week that this was not well tested so far. I found a way to better test it, and found a number of issues. I had to fix and partially re-write this area, so I believe this will be resolved in the next release.

Regards,
Thomas



To unsubscribe from this group and stop receiving emails from it, send an email to h2-database...@googlegroups.com.

too

unread,
Jun 5, 2014, 4:41:45 AM6/5/14
to h2-da...@googlegroups.com
Hi,
I tested with the 1.3.178 and I can confirm that it resolved problem. Tried twice with new jar and problem has not occurred, then tried back with 1.3.176 and replicated it immediately. With "damaged" DB then tried the new jar and it recovered just fine. 

I consider this fixed now, thank you! Looking forward for next release and will use the new jar in the meantime

thanks
Tono

too

unread,
Jun 5, 2014, 6:59:33 AM6/5/14
to h2-da...@googlegroups.com
I just noticed the version is 1.4.178, not 1.3.x.. I will need to wait for stable release then before I can use the jar

Also my jUnit tests failed with inability to create in-memory DB because of missing driver (for jdbc:h2:mem:). not sure whether I'd have to load driver class explicitly for 1.4 but I am falling back to 1.3.x so I will not be investigating that

thanks
Tono

Thomas Mueller

unread,
Jun 10, 2014, 2:11:02 PM6/10/14
to H2 Google Group
Hi,

You could use version 1.4.178, and append ";mv_store=false" to the database URL. This will disable the MVStore file format.

> Also my jUnit tests failed with inability to create in-memory DB because of missing driver (for jdbc:h2:mem:). not sure whether I'd have to load driver class explicitly for 1.4 but I am falling back to 1.3.x so I will not be investigating that

No, you don't have to load the driver explicitly for 1.4.x. There is no change to 1.3.x in this regard. Maybe you need to use Class.forName("org.h2.Driver"); or solve the classpath problem.

Regards,
Thomas

marcolopes

unread,
Jan 8, 2015, 7:52:29 PM1/8/15
to h2-da...@googlegroups.com
Since we upgrade to 1.3.176 (from 1.3.169) in our final product, dozens of users are experiencing problems with damaged databases. I currently don't have access to all the logs, but the most recent was this one:

!SESSION 2015-01-08 16:25:53.347 -----------------------------------------------
eclipse.buildId=unknown
java.version=1.8.0_25
java.vendor=Oracle Corporation
BootLoader constants: OS=win32, ARCH=x86, WS=win32, NL=pt_PT
Command-line arguments:  -os win32 -ws win32 -arch x86

!ENTRY org.projectocolibri.rcp 2 0 2015-01-08 16:26:22.107
!MESSAGE 
!STACK 0
org.h2.jdbc.JdbcSQLException: General error: "java.lang.RuntimeException: page[35624] data leaf table:206 T206 entries:0 parent:20233 keys:null offsets:null parent 20233 expected 0" [50000-176]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
	at org.h2.message.DbException.get(DbException.java:167)
	at org.h2.message.DbException.convert(DbException.java:294)
	at org.h2.engine.Database.openDatabase(Database.java:291)
	at org.h2.engine.Database.<init>(Database.java:254)
	at org.h2.engine.Engine.openSession(Engine.java:57)
	at org.h2.engine.Engine.openSession(Engine.java:164)
	at org.h2.engine.Engine.createSessionAndValidate(Engine.java:142)
	at org.h2.engine.Engine.createSession(Engine.java:125)
	at org.h2.engine.Engine.createSession(Engine.java:27)
	at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:331)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:107)
	at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:91)
	at org.h2.Driver.connect(Driver.java:74)
	at java.sql.DriverManager.getConnection(Unknown Source)
	at java.sql.DriverManager.getConnection(Unknown Source)
	at org.projectocolibri.rcp.colibri.dao.database.connection.ConnectionManager$DRIVERS.checkConnection(ConnectionManager.java:220)
	at org.projectocolibri.rcp.colibri.dao.database.connection.DatabaseParameters.checkConnection(DatabaseParameters.java:76)
	at org.projectocolibri.rcp.colibri.dao.database.ColibriLogin.initialize(ColibriLogin.java:93)
	at org.projectocolibri.rcp.colibri.dao.database.ColibriLogin.process(ColibriLogin.java:60)
	at org.projectocolibri.rcp.colibri.workbench.shells.login.LoginShell$1.widgetSelected(LoginShell.java:178)
	at org.eclipse.swt.widgets.TypedListener.handleEvent(TypedListener.java:248)
	at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:84)
	at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1053)
	at org.eclipse.swt.widgets.Display.runDeferredEvents(Display.java:4169)
	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3758)
	at org.dma.eclipse.swt.custom.CustomShell.openAndSleep(CustomShell.java:47)
	at org.projectocolibri.rcp.colibri.workbench.shells.login.LoginShell.<init>(LoginShell.java:86)
	at org.projectocolibri.rcp.Application.start(Application.java:44)
	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:353)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:180)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:622)
	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:577)
	at org.eclipse.equinox.launcher.Main.run(Main.java:1410)
Caused by: java.lang.RuntimeException: page[35624] data leaf table:206 T206 entries:0 parent:20233 keys:null offsets:null parent 20233 expected 0
	at org.h2.message.DbException.throwInternalError(DbException.java:241)
	at org.h2.index.PageDataIndex.getPage(PageDataIndex.java:247)
	at org.h2.index.PageDataIndex.<init>(PageDataIndex.java:87)
	at org.h2.table.RegularTable.<init>(RegularTable.java:84)
	at org.h2.store.PageStore.addMeta(PageStore.java:1693)
	at org.h2.store.PageStore.redo(PageStore.java:1563)
	at org.h2.store.PageLog.recover(PageLog.java:329)
	at org.h2.store.PageStore.recover(PageStore.java:1407)
	at org.h2.store.PageStore.openExisting(PageStore.java:368)
	at org.h2.store.PageStore.open(PageStore.java:289)
	at org.h2.engine.Database.getPageStore(Database.java:2366)
	at org.h2.engine.Database.open(Database.java:657)
	at org.h2.engine.Database.openDatabase(Database.java:260)
	... 37 more

It's almost certain that these occur when the app is not properly shutdown, and the Datanucleus Persistent Manager is not closed?!

Can you advise to REVERT to 1.3.169 or UPGRADE to 1.4.x (which one?). I would prefer to revert...
Message has been deleted

marcolopes

unread,
Jan 8, 2015, 8:25:24 PM1/8/15
to h2-da...@googlegroups.com
Recovery tool trace:

01-09 01:03:49 jdbc[3]: exception
org.h2.jdbc.JdbcSQLException: Column count does not match; SQL statement:

-- page 24269: data leaf (last) parent: 24276 table: 206 entries: 2 columns: 68
INSERT INTO O_206 VALUES('CFR:2014:181', 'admin', 'EUR:11/04/2012', '1150-008', 'CFR', '100', '', DATE '2014-06-25', DATE '2014-06-25', DATE '2014-06-25', DATE '2014-06-25', DATE '2014-06-25', DATE '2014-06-25', 'admin', 0, 'CL:987', 0, '', NULL, 'zA5BuP3HRVU9P5e8c1jdoQMlwBjHNLKnabmhkfUWUBwkcuMLsqUzbG0PMSVly+JM4TuSupWcyFmk0+Kv6UKA3DD0qziXI/xI2AU75bR0LCG2V8/Ly+HgxA/3Lh1MA5nJaGP6bf9FcHkDr5MTnLL3luNkQN72c7uVgw1P4dl/gcQ=', 2, TIME '16:10:45.39', TIME '16:05:45', TIME '16:53:17.233', '', STRINGDECODE('Av. Almirante Reis, N\u00ba 21 \u2013 3\u00ba Esq.'), 'Lisboa', '', '', '101', 'AE', 'EUR', STRINGDECODE('Av. Almirante Reis, N\u00ba 21 \u2013 3\u00ba Esq.'), 'CFR:2014:181', '252 260 953', 'Pamela Uyara Ferreira de Lima', '', 181, STRINGDECODE('FORM=Presta\u00e7\u00f5es de Servi\u00e7os de Forma\u00e7\u00e3o Profissional'), 0.00, 0.000000, 0.000000, 'CFR:2014', '702', 'CFR', 'CL', 75.000000, 75.000000, 0.000000, 0.000000, 0.000000, 75.000000, 0.000000, 0.000000, 0.000000, 75.000000, '001', 0.000000, 1, TIME '16:05:45', '', 'PT', '', 75.000000, 0, NULL, 0, NULL) [21002-176]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
    at org.h2.message.DbException.get(DbException.java:178)
    at org.h2.message.DbException.get(DbException.java:154)
    at org.h2.message.DbException.get(DbException.java:143)
    at org.h2.command.dml.Insert.prepare(Insert.java:266)
    at org.h2.command.Parser.prepareCommand(Parser.java:248)
    at org.h2.engine.Session.prepareLocal(Session.java:442)
    at org.h2.engine.Session.prepareCommand(Session.java:384)
    at org.h2.jdbc.JdbcConnection.prepareCommand(JdbcConnection.java:1188)
    at org.h2.jdbc.JdbcStatement.executeInternal(JdbcStatement.java:172)
    at org.h2.jdbc.JdbcStatement.execute(JdbcStatement.java:160)
    at org.h2.tools.RunScript.process(RunScript.java:261)
    at org.h2.tools.RunScript.process(RunScript.java:191)
    at org.h2.tools.RunScript.process(RunScript.java:329)
    at org.h2.tools.RunScript.runTool(RunScript.java:142)
    at org.h2.server.web.WebApp.tools(WebApp.java:404)
    at org.h2.server.web.WebApp.process(WebApp.java:242)
    at org.h2.server.web.WebApp.processRequest(WebApp.java:171)
    at org.h2.server.web.WebThread.process(WebThread.java:138)
    at org.h2.server.web.WebThread.run(WebThread.java:94)
    at java.lang.Thread.run(Thread.java:745)

Noel Grandin

unread,
Jan 9, 2015, 2:19:25 AM1/9/15
to h2-da...@googlegroups.com
what does your DB URL look like?

On 2015-01-09 02:52 AM, marcolopes wrote:
> Since we upgrade to *1.3.176* (from 1.3.169) in our final product, dozens of users are experiencing problems with

marcolopes

unread,
Jan 11, 2015, 7:54:06 PM1/11/15
to h2-da...@googlegroups.com
It has been like this for countless software versions...

jdbc:h2:file:database;TRACE_LEVEL_FILE=0;TRACE_LEVEL_SYSTEM_OUT=1

marcolopes

unread,
Jan 11, 2015, 7:54:57 PM1/11/15
to h2-da...@googlegroups.com
I'm opening a new Thread... new errors...
Reply all
Reply to author
Forward
0 new messages