Re: [Resin-interest] inode block/fragment mixup???
On Oct 27, 2008, at 10:49 PM, Mattias Jiderhamn wrote:
I have now filed a report here: http://bugs.caucho.com/view.php?
id=3025
Thanks. I'd already filed a bug, but this has more detail.
-- Scott
/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: 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]
Re: [Resin-interest] inode block/fragment mixup???
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] closin
Re: [Resin-interest] inode block/fragment mixup???
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 +
Re: [Resin-interest] inode block/fragment mixup???
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? Also, does "finer" show anything 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? -- Scott > > > Further below is some detailed information. > > My questions are: > - Is there a limit to the amount of data Resin can keep in a > session? Is > there a setting we should just increase? > - Or is this a bug? Is there any workaround for now? > > Resin version: 3.1.6 Pro > > Session config: > > > 4096 > 30 > > > > Related errors or flavors of the same 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 42 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
