Mantis - Resin
Viewing Issue Advanced Details
3025 major always 10-27-08 22:47 11-04-08 08:35
mate  
ferg  
normal  
closed 3.1.6  
fixed  
none    
none 3.1.8  
0003025: Session lost due to some inode block/fragment mixup
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.
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)

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