double allocation in file (Application used to work on USB memory stick)

[GoogleCodeExporter]

General error: java.lang.RuntimeException: double allocation in file
C:\xxDB.data.db page 2092 blocks 133888-133951 [50000-114]
    at org.h2.message.Message.getSQLException(Message.java:105)
    at org.h2.message.Message.convert(Message.java:277)
    at org.h2.engine.Database.openDatabase(Database.java:246)
    at org.h2.engine.Database.<init>(Database.java:214)
    at org.h2.engine.Engine.openSession(Engine.java:58)
    at org.h2.engine.Engine.openSession(Engine.java:140)
    at org.h2.engine.Engine.getSession(Engine.java:120)
    at
org.h2.engine.SessionFactoryEmbedded.createSession(SessionFactoryEmbedded.java:1
7)
    at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.java:245)
    at org.h2.engine.SessionRemote.createSession(SessionRemote.java:223)
    at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:105)
    at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:89)
    at org.h2.Driver.connect(Driver.java:58)
    at java.sql.DriverManager.getConnection(DriverManager.java:582)
    at java.sql.DriverManager.getConnection(DriverManager.java:185)
...
Caused by: java.lang.RuntimeException: double allocation in file
C:\xxDB.data.db page 2092 blocks 133888-133951
    at org.h2.message.Message.throwInternalError(Message.java:185)
    at org.h2.store.DiskFile.setPageOwner(DiskFile.java:778)
    at org.h2.store.DiskFile.setBlockOwner(DiskFile.java:661)
    at org.h2.store.DiskFile.init(DiskFile.java:410)
    at org.h2.engine.Database.open(Database.java:582)
    at org.h2.engine.Database.openDatabase(Database.java:219)
    ... 13 more

I think lock was created when application shuts down and memory stick was
removed.
I try url option FILE_LOCK=NO, but it does not help.
I also try system options h2.check and h2.check2 but it also does not help.
Could someone please give me a hint how to remove this lock?

Original issue reported on code.google.com by lukaszka...@gmail.com on 3 Jun 2009 at 9:19

[GoogleCodeExporter]

Hi,
This is not a 'lock', it is a data corruption. I have a few questions:

- What is your database URL?
- Do you use Tomcat or another web server? 
    Do you unload or reload the web application?
- Did you use multiple connections?
- The first workarounds is: append ;RECOVER=1 to the database URL.
    Does it work when you do this?
- The second workarounds is: delete the index.db file (it is re-created 
    automatically) and try again. Does it work when you do this?
- The third workarounds is: use the tool org.h2.tools.Recover to create
    the SQL script file, and then re-create the database using this script.
    Does it work when you do this?
- With which version of H2 was this database created?
    You can find it out using:
    select * from information_schema.settings where name='CREATE_BUILD'
- Do you use any settings or special features (for example, the setting 
    LOG=0, or two phase commit, linked tables, cache settings)?
- Is the application multi-threaded?
- What operating system, file system, and virtual machine
    (java -version) do you use?
- Is it (or was it at some point) a networked file system?
- How big is the database (file sizes)?
- Is the database usually closed normally, or is process terminated 
    forcefully or the computer switched off?
- Is it possible to reproduce this problem using a fresh database
    (sometimes, or always)?
- Are there any other exceptions (maybe in the .trace.db file)?
    Could you send them please?
- Do you still have any .trace.db files, and if yes could you send them?
- Could you send the .data.db file where this exception occurs?

Original comment by thomas.t...@gmail.com on 4 Jun 2009 at 7:20

[GoogleCodeExporter]

-Database URL: jdbc:h2:db/xxDB
-I do not use tomcat or another web server, database is used in swing 
application
runnung on USB memory stick.
-No I did not use multiple connections, only one connection is open to 
application,
it is open when application starts, and closed when application is exit.
I use: org.springframework.jdbc.datasource.SingleConnectionDataSource
-appending ;RECOVER=1 to the daabse URL does not help in my case
-Deleting index.db file does not help either
-tool org.h2.tools.Recover creates appropiate sql which I invoke on new db 
instance,
so it seems that this workaround help indeed :), I will ask user to check if 
all data
are in recreated database.
-No I do not use special feautures
-yes application is multi-threaded
-Windows XP, java 1.6 (I am not sure which version client use)
-it was local file system
-database is about 28MB
-yes, database is closed normally - when the application shuts down
-I can not reproduce the problem. But from time to time we have this problem, 
third
user reproted it to us. I think problem occurs when application is in closing 
state
(application user told me that gui is not visable) and user removes memory 
stick from
computer. 
-Yes there is error in .trace.db file:
java.lang.OutOfMemoryError: Java heap space
    at java.util.HashMap.resize(Unknown Source)
    at java.util.HashMap.addEntry(Unknown Source)
    at java.util.HashMap.put(Unknown Source)
    at java.util.HashSet.add(Unknown Source)
    at org.h2.store.DiskFile.freePage(DiskFile.java:652)
    at org.h2.store.DiskFile.setUnused(DiskFile.java:606)
    at org.h2.store.DiskFile.init(DiskFile.java:369)
    at org.h2.engine.Database.open(Database.java:469)
    at org.h2.engine.Database.<init>(Database.java:204)
    at org.h2.engine.Engine.openSession(Engine.java:58)
    at org.h2.engine.Engine.openSession(Engine.java:121)
    at org.h2.engine.Engine.getSession(Engine.java:104)
    at org.h2.engine.Session.createSession(Session.java:229)
    at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:976)
    at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:957)
    at org.h2.Driver.connect(Driver.java:57)
    at java.sql.DriverManager.getConnection(Unknown Source)
    at java.sql.DriverManager.getConnection(Unknown Source)
    at
org.springframework.jdbc.datasource.DriverManagerDataSource.getConnectionFromDri
verManager(DriverManagerDataSource.java:281)
    at
org.springframework.jdbc.datasource.DriverManagerDataSource.getConnectionFromDri
verManager(DriverManagerDataSource.java:269)
    at
org.springframework.jdbc.datasource.DriverManagerDataSource.getConnectionFromDri
verManager(DriverManagerDataSource.java:253)
    at
org.springframework.jdbc.datasource.SingleConnectionDataSource.initConnection(Si
ngleConnectionDataSource.java:244)
    at
org.springframework.jdbc.datasource.SingleConnectionDataSource.getConnection(Sin
gleConnectionDataSource.java:187)
    at
org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUt
ils.java:113)
    at
org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtil
s.java:79)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:382)
    at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:458)
    at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:466)
    at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:474)
    at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:479)
    at
org.springframework.jdbc.core.simple.SimpleJdbcTemplate.queryForObject(SimpleJdb
cTemplate.java:151)
-yes, I can send you the .data.db file

Thanks very much for your help!!! 

Original comment by lukaszka...@gmail.com on 4 Jun 2009 at 5:10

[GoogleCodeExporter]

Sending .data.db file fails via gmail :]

Original comment by lukaszka...@gmail.com on 4 Jun 2009 at 5:20

[GoogleCodeExporter]

I have also received a very similar error on a production system; here is the
relevant part of the stack trace, more info below it:

java.lang.RuntimeException: double allocation in file
C:\Users\<deleted>\.db\server.index.db page 66 blocks 4224-42
87
        at org.h2.message.Message.throwInternalError(Message.java:185)
        at org.h2.store.DiskFile.setPageOwner(DiskFile.java:778)
        at org.h2.store.DiskFile.setBlockOwner(DiskFile.java:661)
        at org.h2.store.DiskFile.init(DiskFile.java:410)
        at org.h2.engine.Database.open(Database.java:584)
        at org.h2.engine.Database.openDatabase(Database.java:219)
        at org.h2.engine.Database.<init>(Database.java:214)
        at org.h2.engine.Engine.openSession(Engine.java:58)
        at org.h2.engine.Engine.openSession(Engine.java:140)
        at org.h2.engine.Engine.getSession(Engine.java:120)
        at org.h2.engine.SessionFactoryEmbedded.createSession(SessionFactoryEmbe
dded.java:17)
        at org.h2.engine.SessionRemote.connectEmbeddedOrServer(SessionRemote.jav
a:245)
        at org.h2.engine.SessionRemote.createSession(SessionRemote.java:223)
        at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:105)
        at org.h2.jdbc.JdbcConnection.<init>(JdbcConnection.java:89)
        at org.h2.Driver.connect(Driver.java:58)
        at org.apache.commons.dbcp.DriverConnectionFactory.createConnection(Driv
erConnectionFactory.java:38)
        at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(Poolable
ConnectionFactory.java:294)
        at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericOb
jectPool.java:1035)
        at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObj
ectPool.java:101)
        at org.apache.commons.dbcp.PoolingDriver.connect(PoolingDriver.java:176)

Unfortunately the user has already recreated the database so I can't check for 
trace
files or try the recover options suggested.

H2 version used: 1.1.114. The DB was created with this version.

Used in a webapp under Jetty. The app is not generally loaded/unloaded - rather 
the
whole container (JVM) is stopped and restarted. This error occurred at startup. 
Not
sure whether or not the preceding shutdown was clean.

It's a multi-threaded application using multiple connections, each used by only 
a
single thread via an apache-commons-DBCP connection pool.

We are using the MVCC feature, soft-ref cache, custom cache size and lock 
timeout.

DB url:
"jdbc:h2:" + databaseDir.getAbsolutePath() +
"/server;MVCC=TRUE;LOCK_TIMEOUT=10000;CACHE_TYPE=SOFT_LRU;CACHE_SIZE=65536"

I will provide more info if I can get any.

Original comment by memor...@gmail.com on 13 Jul 2009 at 11:56

[GoogleCodeExporter]

More details on my issue as described in comment 4:

The data file was small, but the index file has grown absolutely huge: over 40
GIGABYTES!! :
13/07/2009  05:49 PM         5,079,088 server.data.db
13/07/2009  05:49 PM    43,578,974,256 server.index.db
13/07/2009  08:23 PM           200,816 server.trace.db

The trace file is attached (with some irrelevant confidential parts removed) -
basically there are multiple occurrences of the same error, as the user 
restarted
Jetty a few times to try to make the application work. It didn't work, he ended 
up
starting from a clean install.

The "double allocation in file" error started appearing at startup after a 
forced
shutdown of Jetty. Our app is set to close the database on VM exit, but due to 
an
application bug, this time he had to kill Jetty (closed the command window, 
rather
than the usual way of sending Ctrl-C to the process which triggers a clean 
shutdown
hook).

From the user:
----
OS: Microsoft Vista.

JAVA: java version "1.6.0_13"
Java(TM) SE Runtime Environment (build 1.6.0_13-b03)
Java HotSpot(TM) Client VM (build 11.3-b02, mixed mode, sharing)

DISK: NTFS file system

The only other 'odd' thing I can think of is that my machine may have gone into
standby and then run out of battery once a while ago.

Original comment by memor...@gmail.com on 14 Jul 2009 at 6:58

Attachments:

• server.trace.db

[GoogleCodeExporter]

I don't know whether this is relevant, but we have a few instances of stack 
traces
like the following in our log shortly before the problem described in Comment 
4. They
are various JDBC calls which have been executed during shutdown, and have 
therefore
failed.

It's a bug in our application that these were run at all (shouldn't be trying 
perform
database operations during the shutdown process after the DB is closed) - just 
wanted
to mention them in case they have any impact on H2.

07-13 17:09:33 jdbc[11]: SQLException
org.h2.jdbc.JdbcSQLException: Database is already closed (to disable automatic
closing at VM shutdown, add ";DB_CLOSE_ON_EXIT=FALSE" to the db URL) [90121-114]
    at org.h2.message.Message.getSQLException(Message.java:105)
    at org.h2.message.Message.getSQLException(Message.java:116)
    at org.h2.message.Message.getSQLException(Message.java:75)
    at org.h2.message.Message.getSQLException(Message.java:151)
    at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1307)
    at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1280)
    at org.h2.jdbc.JdbcConnection.getAutoCommit(JdbcConnection.java:375)
    at
org.apache.commons.dbcp.DelegatingConnection.getAutoCommit(DelegatingConnection.
java:304)
07-13 17:09:34 jdbc[2]: SQLException
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-114]
    at org.h2.message.Message.getSQLException(Message.java:105)
    at org.h2.message.Message.getSQLException(Message.java:116)
    at org.h2.message.Message.getSQLException(Message.java:75)
    at org.h2.message.Message.getSQLException(Message.java:151)
    at org.h2.jdbc.JdbcStatement.checkClosed(JdbcStatement.java:869)
    at org.h2.jdbc.JdbcPreparedStatement.checkClosed(JdbcPreparedStatement.java:1416)
    at org.h2.jdbc.JdbcStatement.checkClosed(JdbcStatement.java:846)
    at org.h2.jdbc.JdbcPreparedStatement.clearParameters(JdbcPreparedStatement.java:195)
    at
org.apache.commons.dbcp.DelegatingPreparedStatement.clearParameters(DelegatingPr
eparedStatement.java:157)
07-13 17:09:33 jdbc[2]: SQLException
org.h2.jdbc.JdbcSQLException: Database is already closed (to disable automatic
closing at VM shutdown, add ";DB_CLOSE_ON_EXIT=FALSE" to the db URL) [90121-114]
    at org.h2.message.Message.getSQLException(Message.java:105)
    at org.h2.message.Message.getSQLException(Message.java:116)
    at org.h2.message.Message.getSQLException(Message.java:75)
    at org.h2.message.Message.getSQLException(Message.java:151)
    at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1307)
    at org.h2.jdbc.JdbcStatement.checkClosed(JdbcStatement.java:871)
    at org.h2.jdbc.JdbcPreparedStatement.checkClosed(JdbcPreparedStatement.java:1416)
    at org.h2.jdbc.JdbcStatement.checkClosed(JdbcStatement.java:846)
    at org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:91)
    at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPrepa
redStatement.java:93)
07-13 17:09:33 jdbc[2]: SQLException
org.h2.jdbc.JdbcSQLException: Database is already closed (to disable automatic
closing at VM shutdown, add ";DB_CLOSE_ON_EXIT=FALSE" to the db URL) [90121-114]
    at org.h2.message.Message.getSQLException(Message.java:105)
    at org.h2.message.Message.getSQLException(Message.java:116)
    at org.h2.message.Message.getSQLException(Message.java:75)
    at org.h2.message.Message.getSQLException(Message.java:151)
    at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1307)
    at org.h2.jdbc.JdbcConnection.checkClosedForWrite(JdbcConnection.java:1291)
    at org.h2.jdbc.JdbcConnection.rollback(JdbcConnection.java:420)
    at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:328)

Original comment by memor...@gmail.com on 14 Jul 2009 at 7:10

[GoogleCodeExporter]

I don't think there is an easy fix for this problem, so I'm closing
the issue. My plan is to change the storage mechanism to 'page store',
which is now the top priority - see 
http://www.h2database.com/html/roadmap.html
I hope this will resolve the problem.

The exception 'double allocation in .. *.index.db'
can probably be solved in the current version by using LOG=2, see
http://www.h2database.com/html/grammar.html#set_log
(with the 'page store', the command SET LOG 2 will have no effect,
but now it has).

The 43 GB index file is most likely caused by a index file corruption,
it should also be possible to avoid this using SET LOG 2.
If you delete the .index.db file, it will be re-created.

Original comment by thomas.t...@gmail.com on 18 Jul 2009 at 11:06

• Changed state: InRoadmap