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: com.caucho.sql.ManagedConnectionImpl
[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
