Mantis Bugtracker
  

Viewing Issue Advanced Details Jump to Notes ] View Simple ] 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 Platform
Status closed   OS
Projection none   OS Version
ETA none Fixed in Version 3.1.8 Product Version 3.1.6
  Product Build
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.
Steps To Reproduce
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