Mantis Bugtracker
  

Viewing Issue Simple Details Jump to Notes ] View Advanced ] Issue History ] Print ]
ID 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[^]
Copyright © 2000 - 2005 Mantis Group
30 total queries executed.
26 unique queries executed.
Powered by Mantis Bugtracker