I have now filed a report here: http://bugs.caucho.com/view.php?id=3025
/Mattias
Mattias Jiderhamn wrote (2008-10-24 20:30):
> Scott Ferguson wrote (2008-10-23 18:39):
>> On Oct 22, 2008, at 12:06 PM, Mattias Jiderhamn wrote:
>>
>>
>>> We have a strange problem with Resin that looks like a bug but might
>>> be
>>> some configuration issue.
>>>
>>> We hit the bug while storing more than the usual amount of data in a
>>> session (during a process that takes quite a lot of time).
>>> If we narrow things down so we store the same kind of data, although
>>> not
>>> as much (and not using so much time), the error does not come about.
>>> The symptoms are that the slow 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.
>>> There
>>> are 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.
>>>
>>
>> Do you know how large the session is?
> >From what I can see about 7 MB.
>
>> Also, does "finer" show anything interesting?
>>
> See below if there is anything you consider interesting.
>
>> There may be a limit at 64M of session data, but I doubt you're
>> hitting that. It's possible there's an off-by-one issue at one of the
>> boundaries (since the data is split into fragments). Does adding 1 to
>> the session length still produce the same error?
>>
> A quick test with session.setAttribute("foo", "bar") actually seemed
> to do the trick!
> Is there anything specific you would like me to try with regards to this?
>
>
>
> Here is the finer log:
> ...
> [18:00:06.234] Transaction[01:908024ea] committing
> [18:00:06.234] commit-local:
> [EMAIL PROTECTED]
> [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)
> ...
> ------------------------------------------------------------------------
>
> _______________________________________________
> resin-interest mailing list
> resin-interest@caucho.com
> http://maillist.caucho.com/mailman/listinfo/resin-interest
>
_______________________________________________
resin-interest mailing list
resin-interest@caucho.com
http://maillist.caucho.com/mailman/listinfo/resin-interest
