0003025: Session lost due to some inode block/fragment mixup

Viewing Issue Simple Details [ Jump to Notes ]

[ View Advanced ] [ Issue History ] [ Print ]

Category

Severity

Reproducibility

Date Submitted

Last Update

0003025

[Resin]

major

always

10-27-08 22:47

11-04-08 08:35

Reporter

mate

View Status

public

Assigned To

ferg

Priority

normal

Resolution

fixed

Status

closed

Product Version

3.1.6

Summary

0003025: Session lost due to some inode block/fragment mixup

Description

We hit the bug while storing about 7 MB of data in a session.
If we narrow things down so we store the same kind of data, although not as much, the error does not come about.
The symptoms are that the request seems to finish correcly and the data is returned to the browser, however on the next request the session does no longer exist. Other sessions does not seem to be affected.

The errors in the log file which makes me believe the session is lost during serializing/deserializing.

With the same input data, the error is always reproducible. However, adding session.setAttribute("foo", "bar") makes it go away.

Additional Information

A finer log:
[18:00:06.234] Transaction[01:908024ea] committing
[18:00:06.234] commit-local: com.caucho.sql.ManagedConnectionImpl$LocalTransactionImpl@1005abc
[18:00:06.328] idle PoolItem[jdbc/exder,7,ManagedConnectionImpl]
[18:00:07.593] Table[srun_:2] allocating block 270 fragment
[18:00:07.609] Table[srun_:2] allocating block 271 fragment
[18:00:07.609] Table[srun_:2] allocating block 272 fragment
(and so on...)
[18:00:08.312] Table[srun_:2] allocating block 333 fragment
[18:00:08.312] Table[srun_:2] allocating block 334 fragment
[18:00:08.343] java.lang.IllegalStateException: block/fragment mixup
[18:00:08.343] at com.caucho.db.store.Inode.writeBlockAddr(Inode.java:1078)
[18:00:08.343] at com.caucho.db.store.Inode.appendBlock(Inode.java:492)
[18:00:08.343] at com.caucho.db.store.Inode.append(Inode.java:388)
[18:00:08.343] at com.caucho.db.store.BlobOutputStream.flushBlock(BlobOutputStream.java:188)
[18:00:08.343] at com.caucho.db.store.BlobOutputStream.write(BlobOutputStream.java:117)
[18:00:08.343] at com.caucho.db.table.BlobColumn.setStream(BlobColumn.java:179)
[18:00:08.343] at com.caucho.db.table.BlobColumn.set(BlobColumn.java:267)
[18:00:08.343] at com.caucho.db.sql.UpdateQuery.execute(UpdateQuery.java:110)
[18:00:08.343] at com.caucho.db.jdbc.PreparedStatementImpl.execute(PreparedStatementImpl.java:345)
[18:00:08.343] at com.caucho.db.jdbc.PreparedStatementImpl.executeUpdate(PreparedStatementImpl.java:313)
[18:00:08.343] at com.caucho.server.cluster.FileBacking.storeSelfUpdate(FileBacking.java:524)
[18:00:08.343] at com.caucho.server.cluster.FileBacking.storeSelf(FileBacking.java:474)
[18:00:08.343] at com.caucho.server.cluster.FileStore.store(FileStore.java:169)
[18:00:08.343] at com.caucho.server.cluster.ClusterObject.store(ClusterObject.java:414)
[18:00:08.343] at com.caucho.server.session.SessionImpl.save(SessionImpl.java:960)
[18:00:08.343] at com.caucho.server.session.SessionImpl.saveAfterRequest(SessionImpl.java:946)
[18:00:08.343] at com.caucho.server.session.SessionImpl.finish(SessionImpl.java:908)
[18:00:08.343] at com.caucho.server.connection.AbstractHttpRequest.finish(AbstractHttpRequest.java:2506)
[18:00:08.343] at com.caucho.server.http.HttpRequest.finish(HttpRequest.java:1466)
[18:00:08.343] at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:212)
[18:00:08.343] at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:266)
[18:00:08.343] at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:269)
[18:00:08.343] at com.caucho.server.port.TcpConnection.run(TcpConnection.java:603)
[18:00:08.343] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[18:00:08.343] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[18:00:08.343] at java.lang.Thread.run(Thread.java:595)
[18:00:08.421] Http[15] no-keepalive
[18:00:08.421] Tcp[,15] closing connection TcpConnection[id=http--80-15,socket=JniSocketImpl$15452578[90827352,fd=4488],
port=Port[null:80]], total=13
(... six more...)
[18:01:06.890] Tcp[,6] com.caucho.vfs.ClientDisconnectException: client timeout
[18:01:06.890] Tcp[,6] closing connection TcpConnection[id=http--80-6,socket=JniSocketImpl$5256758[90830936,fd=4076],por
t=Port[null:80]], total=11
[18:03:04.875] Database[/c:/temp/resin-sessions]: DELETE FROM srun_ WHERE access_time + 5 * expire_interval / 4 < ?
[18:03:04.875] where-1: static null
[18:03:04.875] where-0: FromItem[srun_ AS srun_] ((srun_.access_time + ((5 * srun_.expire_interval) / 4)) < ?0)
[18:03:04.875] java.lang.ArrayIndexOutOfBoundsException: 48685569
[18:03:04.875] at com.caucho.db.store.Store.deleteFragment(Store.java:1035)
[18:03:04.875] at com.caucho.db.store.Inode.remove(Inode.java:844)
[18:03:04.875] at com.caucho.db.store.Transaction.writeData(Transaction.java:568)
[18:03:04.875] at com.caucho.db.sql.QueryContext.unlock(QueryContext.java:537)
[18:03:04.875] at com.caucho.db.sql.RowIterateExpr.nextBlock(RowIterateExpr.java:86)
[18:03:04.875] at com.caucho.db.sql.Query.nextBlock(Query.java:721)
[18:03:04.875] at com.caucho.db.sql.Query.nextTuple(Query.java:698)
[18:03:04.875] at com.caucho.db.sql.DeleteQuery.execute(DeleteQuery.java:81)
[18:03:04.875] at com.caucho.db.jdbc.PreparedStatementImpl.execute(PreparedStatementImpl.java:345)
[18:03:04.875] at com.caucho.db.jdbc.PreparedStatementImpl.executeUpdate(PreparedStatementImpl.java:313)
[18:03:04.875] at com.caucho.server.cluster.FileBacking.clearOldObjects(FileBacking.java:270)
[18:03:04.875] at com.caucho.server.cluster.FileStore.clearOldObjects(FileStore.java:115)
[18:03:04.875] at com.caucho.server.cluster.StoreManager.handleAlarm(StoreManager.java:636)
[18:03:04.875] at com.caucho.util.Alarm.handleAlarm(Alarm.java:375)
[18:03:04.875] at com.caucho.util.Alarm.run(Alarm.java:345)
[18:03:04.875] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[18:03:04.875] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[18:03:04.875] at java.lang.Thread.run(Thread.java:595)
[18:03:05.750] FileBacking[srun_] purged 1 old sessions
...
[18:08:05.390] Database[/c:/temp/resin-sessions]: DELETE FROM srun_ WHERE access_time + 5 * expire_interval / 4 < ?
[18:08:05.390] where-1: static null
[18:08:05.390] where-0: FromItem[srun_ AS srun_] ((srun_.access_time + ((5 * srun_.expire_interval) / 4)) < ?0)

Different flavors of the error:
[18:41:24.000] java.lang.IllegalStateException: block/fragment mixup
[18:41:24.000] at com.caucho.db.store.Inode.writeBlockAddr(Inode.java:1078)
[18:41:24.000] at com.caucho.db.store.Inode.appendBlock(Inode.java:492)
[18:41:24.000] at com.caucho.db.store.Inode.append(Inode.java:388)
[18:41:24.000] at com.caucho.db.store.BlobOutputStream.flushBlock(BlobOutputStream.java:188)
[18:41:24.000] at com.caucho.db.store.BlobOutputStream.write(BlobOutputStream.java:117)
[18:41:24.000] at com.caucho.db.table.BlobColumn.setStream(BlobColumn.java:179)
[18:41:24.000] at com.caucho.db.table.BlobColumn.set(BlobColumn.java:267)
[18:41:24.000] at com.caucho.db.sql.UpdateQuery.execute(UpdateQuery.java:110)
[18:41:24.000] at com.caucho.db.jdbc.PreparedStatementImpl.execute(PreparedStatementImpl.java:345)
[18:41:24.000] at com.caucho.db.jdbc.PreparedStatementImpl.executeUpdate(PreparedStatementImpl.java:313)
[18:41:24.000] at com.caucho.server.cluster.FileBacking.storeSelfUpdate(FileBacking.java:524)
[18:41:24.000] at com.caucho.server.cluster.FileBacking.storeSelf(FileBacking.java:474)
[18:41:24.000] at com.caucho.server.cluster.FileStore.store(FileStore.java:169)
[18:41:24.000] at com.caucho.server.cluster.ClusterObject.store(ClusterObject.java:414)
[18:41:24.000] at com.caucho.server.session.SessionImpl.save(SessionImpl.java:960)
[18:41:24.000] at com.caucho.server.session.SessionImpl.saveAfterRequest(SessionImpl.java:946)
[18:41:24.000] at com.caucho.server.session.SessionImpl.finish(SessionImpl.java:908)
[18:41:24.000] at com.caucho.server.connection.AbstractHttpRequest.finish(AbstractHttpRequest.java:2506)
[18:41:24.000] at com.caucho.server.http.HttpRequest.finish(HttpRequest.java:1466)
[18:41:24.000] at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:212)
[18:41:24.000] at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:266)
[18:41:24.000] at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:269)
[18:41:24.000] at com.caucho.server.port.TcpConnection.run(TcpConnection.java:603)
[18:41:24.000] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[18:41:24.000] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[18:41:24.000] at java.lang.Thread.run(Thread.java:595)

[18:47:31.281] java.lang.IllegalStateException: Table[srun_:2]: inode
block 420000 has 0 fragment
[18:47:31.281] at com.caucho.db.store.Inode.stateError(Inode.java:1164)
[18:47:31.281] at com.caucho.db.store.Inode.remove(Inode.java:836)
[18:47:31.281] at com.caucho.db.store.Transaction.writeData(Transaction.java:568)
[18:47:31.281] at com.caucho.db.sql.QueryContext.unlock(QueryContext.java:537)
[18:47:31.281] at com.caucho.db.sql.RowIterateExpr.nextBlock(RowIterateExpr.java:86)
[18:47:31.281] at com.caucho.db.sql.Query.nextBlock(Query.java:721)
[18:47:31.281] at com.caucho.db.sql.Query.nextTuple(Query.java:698)
[18:47:31.281] at com.caucho.db.sql.DeleteQuery.execute(DeleteQuery.java:81)
[18:47:31.281] at com.caucho.db.jdbc.PreparedStatementImpl.execute(PreparedStatementImpl.java:345)
[18:47:31.281] at com.caucho.db.jdbc.PreparedStatementImpl.executeUpdate(PreparedStatementImpl.java:313)
[18:47:31.281] at com.caucho.server.cluster.FileBacking.clearOldObjects(FileBacking.java:270)
[18:47:31.281] at com.caucho.server.cluster.FileStore.clearOldObjects(FileStore.java:115)
[18:47:31.281] at com.caucho.server.cluster.StoreManager.handleAlarm(StoreManager.java:636)
[18:47:31.281] at com.caucho.util.Alarm.handleAlarm(Alarm.java:375)
[18:47:31.281] at com.caucho.util.Alarm.run(Alarm.java:345)
[18:47:31.281] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[18:47:31.281] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[18:47:31.281] at java.lang.Thread.run(Thread.java:595)

[17:24:07.351] java.lang.IllegalStateException: block/fragment mixup
[17:24:07.351] at com.caucho.db.store.Inode.readBlockAddr(Inode.java:1047)
[17:24:07.351] at com.caucho.db.store.Inode.read(Inode.java:319)
[17:24:07.351] at com.caucho.db.store.BlobInputStream.read(BlobInputStream.java:114)
[17:24:07.351] at com.caucho.vfs.VfsStream.read(VfsStream.java:140)
[17:24:07.351] at com.caucho.vfs.Crc64Stream.read(Crc64Stream.java:84)
[17:24:07.351] at com.caucho.vfs.ReadStream.readBuffer(ReadStream.java:1015)
[17:24:07.351] at com.caucho.vfs.ReadStream.read(ReadStream.java:425)
[17:24:07.351] at java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2266)
[17:24:07.351] at java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2279)
[17:24:07.351] at java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:2750)
[17:24:07.351] at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:780)
[17:24:07.351] at java.io.ObjectInputStream.<init>(ObjectInputStream.java:280)
[17:24:07.351] at com.caucho.server.session.SessionManager$DistributedObjectInputStream.<init>(SessionManager.java:1749)
[17:24:07.351] at com.caucho.server.session.SessionManager.load(SessionManager.java:1552)
[17:24:07.351] at com.caucho.server.cluster.ClusterObject.load(ClusterObject.java:299)
[17:24:07.351] at com.caucho.server.cluster.FileBacking.loadSelf(FileBacking.java:314)
[17:24:07.351] at com.caucho.server.cluster.FileStore.load(FileStore.java:147)
[17:24:07.351] at com.caucho.server.cluster.ClusterObject.load(ClusterObject.java:268)
[17:24:07.351] at com.caucho.server.session.SessionImpl.load(SessionImpl.java:774)
[17:24:07.351] at com.caucho.server.session.SessionManager.getSession(SessionManager.java:1363)
[17:24:07.351] at com.caucho.server.connection.AbstractHttpRequest.createSession(AbstractHttpRequest.java:1517)
[17:24:07.351] at com.caucho.server.connection.AbstractHttpRequest.getSession(AbstractHttpRequest.java:1326)
[17:24:07.351] at se.exder.servlet.SessionCacheFilter.doFilter(SessionCacheFilter.java:34)
[17:24:07.351] at com.caucho.server.dispatch.FilterFilterChain.doFilter(FilterFilterChain.java:87)
[17:24:07.351] at com.caucho.server.cache.CacheFilterChain.doFilter(CacheFilterChain.java:194)
[17:24:07.351] at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:187)
[17:24:07.351] at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:266)
[17:24:07.351] at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:270)
[17:24:07.351] at com.caucho.server.port.TcpConnection.run(TcpConnection.java:678)
[17:24:07.351] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[17:24:07.351] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[17:24:07.351] at java.lang.Thread.run(Thread.java:619)
[17:24:07.355] java.lang.ArrayIndexOutOfBoundsException: 16515117
[17:24:07.355] at com.caucho.db.store.Store.deleteFragment(Store.java:1041)
[17:24:07.355] at com.caucho.db.store.Inode.remove(Inode.java:844)
[17:24:07.355] at com.caucho.db.store.Transaction.writeData(Transaction.java:568)
[17:24:07.355] at com.caucho.db.sql.QueryContext.unlock(QueryContext.java:537)
[17:24:07.355] at com.caucho.db.sql.UpdateQuery.execute(UpdateQuery.java:118)
[17:24:07.355] at com.caucho.db.jdbc.PreparedStatementImpl.execute(PreparedStatementImpl.java:345)
[17:24:07.355] at com.caucho.db.jdbc.PreparedStatementImpl.executeUpdate(PreparedStatementImpl.java:313)
[17:24:07.355] at com.caucho.server.cluster.FileBacking.storeSelfUpdate(FileBacking.java:524)
[17:24:07.355] at com.caucho.server.cluster.FileBacking.storeSelf(FileBacking.java:474)
[17:24:07.355] at com.caucho.server.cluster.FileStore.store(FileStore.java:169)
[17:24:07.355] at com.caucho.server.cluster.ClusterObject.store(ClusterObject.java:414)
[17:24:07.355] at com.caucho.server.session.SessionImpl.save(SessionImpl.java:952)
[17:24:07.355] at com.caucho.server.connection.AbstractHttpRequest.saveSession(AbstractHttpRequest.java:2488)
[17:24:07.355] at com.caucho.server.connection.AbstractHttpResponse.sendRedirect(AbstractHttpResponse.java:655)

[13:31:29.115] java.lang.IllegalStateException: Table[srun_:2]: inode
block 420000 has invalid fragment ee800036ee807871
[13:31:29.115] at com.caucho.db.store.Inode.stateError(Inode.java:1164)
[13:31:29.115] at com.caucho.db.store.Inode.remove(Inode.java:841)
[13:31:29.115] at com.caucho.db.store.Transaction.writeData(Transaction.java:568)
[13:31:29.115] at com.caucho.db.sql.QueryContext.unlock(QueryContext.java:537)
[13:31:29.115] at com.caucho.db.sql.UpdateQuery.execute(UpdateQuery.java:118)
[13:31:29.115] at com.caucho.db.jdbc.PreparedStatementImpl.execute(PreparedStatementImpl.java:345)
[13:31:29.115] at com.caucho.db.jdbc.PreparedStatementImpl.executeUpdate(PreparedStatementImpl.java:313)
[13:31:29.115] at com.caucho.server.cluster.FileBacking.storeSelfUpdate(FileBacking.java:524)
[13:31:29.115] at com.caucho.server.cluster.FileBacking.storeSelf(FileBacking.java:474)
[13:31:29.115] at com.caucho.server.cluster.FileStore.store(FileStore.java:169)
[13:31:29.115] at com.caucho.server.cluster.ClusterObject.store(ClusterObject.java:414)
[13:31:29.115] at com.caucho.server.session.SessionImpl.save(SessionImpl.java:952)
[13:31:29.115] at com.caucho.server.session.SessionImpl.saveAfterRequest(SessionImpl.java:938)
[13:31:29.115] at com.caucho.server.session.SessionImpl.finish(SessionImpl.java:900)
[13:31:29.115] at com.caucho.server.connection.AbstractHttpRequest.finish(AbstractHttpRequest.java:2509)
[13:31:29.115] at com.caucho.server.http.HttpRequest.finish(HttpRequest.java:1467)
[13:31:29.115] at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:219)
[13:31:29.115] at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:266)
[13:31:29.115] at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:270)
[13:31:29.115] at com.caucho.server.port.TcpConnection.run(TcpConnection.java:678)
[13:31:29.115] at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721)
[13:31:29.115] at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643)
[13:31:29.115] at java.lang.Thread.run(Thread.java:619)

Attached Files

Relationships

Notes
(0003530) ferg 11-04-08 08:35	server/01q3

Issue History
Date Modified	Username	Field	Change
10-27-08 22:47	mate	New Issue
10-27-08 22:48	mate	Issue Monitored: mate
11-04-08 08:35	ferg	Note Added: 0003530
11-04-08 08:35	ferg	Assigned To	=> ferg
11-04-08 08:35	ferg	Status	new => closed
11-04-08 08:35	ferg	Resolution	open => fixed
11-04-08 08:35	ferg	Fixed in Version	=> 3.1.8

Mantis 1.0.0rc3[^]

30 total queries executed.
26 unique queries executed.