Re: null lastPage at restoreAfterSerialization
I know this has been a while, but was this ever resolved? We're seeing the
same problem. And, because of this problem, Wicket is never cleaning up old
session pagemap files which leads to oodles of files in our tomcat work
directory.
Thanks,
Meetesh
On Sat, Nov 22, 2008 at 5:55 AM, Carlos Pita carlosjosep...@gmail.comwrote:
Matej,
forget what I said yesterday about session lastAccessedDate, I've
debugged it in detail and tomcat is doing its part fine, I was
confused by a sequence of logs that implied that the session was
swapped out before a page was added to its pagemap. But later I found
out that this wasn't the usual pattern so I included more log output
here and there. And now it seems as if the pagemap instance that is
swapped out isn't the same one where the page was first put. Below I
copied the pertinent fragments of code and one example of output
showing the anomaly:
1) What follows is in order to identify each pagemap instance (with
thisNum):
private static final class SecondLevelCachePageMap extends PageMap
{
private static int pageMapNum = 0;
private int thisNum;
private SecondLevelCachePageMap(String sessionId, Application
application, String name)
{
synchronized (SecondLevelCachePageMap.class)
{
thisNum = pageMapNum++;
}
}
2) Now for the logging part
a) First when a page is put into the pagemap
public void put(Page page)
{
if (!page.isPageStateless())
{
Session session = getSession();
String sessionId = session.getId();
if (sessionId != null !session.isSessionInvalidated())
{
// the id could have changed from null during request
this.sessionId = sessionId;
log.error(put + sessionId + + thisNum);
getStore().storePage(sessionId, page);
setLastPage(page);
dirty();
}
}
}
b) Then when a pagemap is swapped out (writeObject):
private void writeObject(java.io.ObjectOutputStream s) throws IOException
{
s.defaultWriteObject();
IPageStore store = getPageStore();
if (sessionId != null store instanceof IClusteredPageStore == false)
{
-- if (lastPage == null) log.error(writeObject1 + sessionId +
+ thisNum); --
Object page = lastPage;
if (store instanceof ISerializationAwarePageStore)
{
page = (ISerializationAwarePageStore)store).prepareForSerialization(...
-- if (page == null) log.error(writeObject2 + sessionId + +
thisNum); --
}
}
.
}
Finally, the output looks like:
2008-11-22 04:43:58,841 PAGE 19ACC6B64E22346D494E742A0E859B52 29
other pages in other sessions follows
2008-11-22 04:44:00,486 put 33932E31AE77206B5E556266170B4827 33
2008-11-22 04:44:00,201 put C6423FDD58C4B31C080700E4455F158C
and about 120 secs later:
2008-11-22 04:46:36,432 writeObject1 19ACC6B64E22346D494E742A0E859B52 30
2008-11-22 04:46:36,432 writeObject2 19ACC6B64E22346D494E742A0E859B52 30
In every case I've seen the instance num for the writeObject1/2 logs
was one plus the num for the put log in the same session. I think that
here the second pagemap (30) is created with a default lastPage = null
that never is assigned a non null page, because put is being called on
the first pagemap (29) instead.
I still don't know where the second pagemap is created, but I'm getting
closer.
HIH
-Carlos
On Thu, Nov 20, 2008 at 3:05 AM, Carlos Pita carlosjosep...@gmail.com
wrote:
Hi Matej,
I'm browsing your changes. Please notice that according to my own
debugging it's lastPage itself that is null and not only the result of
prepareForSerialization. So I don't think the warning PageStore
prepared non-null page as null for serialization will ever be
reached. Anyway, I will add other warnings and keep you informed of
the output as soon as I can. This is really tricky to debug because up
til today I'm only able to reproduce it at full scale in a production
environment.
Do you have any idea why a lastPage would be null after 120 secs of
the request that created the session? Specially for sessions that
don't survive that first request. An exception that could avoid
request cycle to detach the session maybe?
Thanks!
-Carlos
On Wed, Nov 19, 2008 at 7:18 PM, Matej Knopp matej.kn...@gmail.com
wrote:
This really is weird. I added couple of warnings and null check to 1.4
trunk. I wonder if that helps it though.
-Matej
On Wed, Nov 19, 2008 at 12:44 PM, Carlos Pita carlosjosep...@gmail.com
wrote:
The last one of the saga for now, I badly need to sleep.
I've been sampling tomcat work dir every second:
i=0; while [[ i -le 300 ]]; do echo $i; ls -lt /u01/tomcatWork/_
/tmp/work$i; sleep 1; i=$((i + 1)); done
Then I greped a number of session ids corresponding to
restoreAfterSerialization errors and every one of them appears in zero
or one samples at most. With maxIdleTime = 120 secs the pattern is
this:
/u01/tomcatWork/_/wicketServlet-fileStore/sessionid created at
T - 120 secs
Re: null lastPage at restoreAfterSerialization
Unfortunately I wasn't able to reproduce this so I don't think this
got resolved.
-Matej
On Thu, Mar 5, 2009 at 8:47 PM, Meetesh Karia meetesh.ka...@gmail.com wrote:
I know this has been a while, but was this ever resolved? We're seeing the
same problem. And, because of this problem, Wicket is never cleaning up old
session pagemap files which leads to oodles of files in our tomcat work
directory.
Thanks,
Meetesh
On Sat, Nov 22, 2008 at 5:55 AM, Carlos Pita carlosjosep...@gmail.comwrote:
Matej,
forget what I said yesterday about session lastAccessedDate, I've
debugged it in detail and tomcat is doing its part fine, I was
confused by a sequence of logs that implied that the session was
swapped out before a page was added to its pagemap. But later I found
out that this wasn't the usual pattern so I included more log output
here and there. And now it seems as if the pagemap instance that is
swapped out isn't the same one where the page was first put. Below I
copied the pertinent fragments of code and one example of output
showing the anomaly:
1) What follows is in order to identify each pagemap instance (with
thisNum):
private static final class SecondLevelCachePageMap extends PageMap
{
private static int pageMapNum = 0;
private int thisNum;
private SecondLevelCachePageMap(String sessionId, Application
application, String name)
{
synchronized (SecondLevelCachePageMap.class)
{
thisNum = pageMapNum++;
}
}
2) Now for the logging part
a) First when a page is put into the pagemap
public void put(Page page)
{
if (!page.isPageStateless())
{
Session session = getSession();
String sessionId = session.getId();
if (sessionId != null !session.isSessionInvalidated())
{
// the id could have changed from null during request
this.sessionId = sessionId;
log.error(put + sessionId + + thisNum);
getStore().storePage(sessionId, page);
setLastPage(page);
dirty();
}
}
}
b) Then when a pagemap is swapped out (writeObject):
private void writeObject(java.io.ObjectOutputStream s) throws IOException
{
s.defaultWriteObject();
IPageStore store = getPageStore();
if (sessionId != null store instanceof IClusteredPageStore == false)
{
-- if (lastPage == null) log.error(writeObject1 + sessionId +
+ thisNum); --
Object page = lastPage;
if (store instanceof ISerializationAwarePageStore)
{
page = (ISerializationAwarePageStore)store).prepareForSerialization(...
-- if (page == null) log.error(writeObject2 + sessionId + +
thisNum); --
}
}
.
}
Finally, the output looks like:
2008-11-22 04:43:58,841 PAGE 19ACC6B64E22346D494E742A0E859B52 29
other pages in other sessions follows
2008-11-22 04:44:00,486 put 33932E31AE77206B5E556266170B4827 33
2008-11-22 04:44:00,201 put C6423FDD58C4B31C080700E4455F158C
and about 120 secs later:
2008-11-22 04:46:36,432 writeObject1 19ACC6B64E22346D494E742A0E859B52 30
2008-11-22 04:46:36,432 writeObject2 19ACC6B64E22346D494E742A0E859B52 30
In every case I've seen the instance num for the writeObject1/2 logs
was one plus the num for the put log in the same session. I think that
here the second pagemap (30) is created with a default lastPage = null
that never is assigned a non null page, because put is being called on
the first pagemap (29) instead.
I still don't know where the second pagemap is created, but I'm getting
closer.
HIH
-Carlos
On Thu, Nov 20, 2008 at 3:05 AM, Carlos Pita carlosjosep...@gmail.com
wrote:
Hi Matej,
I'm browsing your changes. Please notice that according to my own
debugging it's lastPage itself that is null and not only the result of
prepareForSerialization. So I don't think the warning PageStore
prepared non-null page as null for serialization will ever be
reached. Anyway, I will add other warnings and keep you informed of
the output as soon as I can. This is really tricky to debug because up
til today I'm only able to reproduce it at full scale in a production
environment.
Do you have any idea why a lastPage would be null after 120 secs of
the request that created the session? Specially for sessions that
don't survive that first request. An exception that could avoid
request cycle to detach the session maybe?
Thanks!
-Carlos
On Wed, Nov 19, 2008 at 7:18 PM, Matej Knopp matej.kn...@gmail.com
wrote:
This really is weird. I added couple of warnings and null check to 1.4
trunk. I wonder if that helps it though.
-Matej
On Wed, Nov 19, 2008 at 12:44 PM, Carlos Pita carlosjosep...@gmail.com
wrote:
The last one of the saga for now, I badly need to sleep.
I've been sampling tomcat work dir every second:
i=0; while [[ i -le 300 ]]; do echo $i; ls -lt /u01/tomcatWork/_
/tmp/work$i; sleep 1; i=$((i + 1)); done
Then I greped a number of session ids corresponding to
restoreAfterSerialization errors and every one of them appears in zero
Re: null lastPage at restoreAfterSerialization
I'm not sure I can provide any additional information as we just started
looking into it (though we've been seeing it for a while). For the time
being, I'm just going to set up a cron job to remove old pagemap files.
Perhaps we could make the restore block allow a null lastPage? Btw - what
happens if the only request a client ever makes is for a resource? Will
lastPage ever be set?
Thanks!
Meetesh
On Thu, Mar 5, 2009 at 1:51 PM, Matej Knopp matej.kn...@gmail.com wrote:
Unfortunately I wasn't able to reproduce this so I don't think this
got resolved.
-Matej
On Thu, Mar 5, 2009 at 8:47 PM, Meetesh Karia meetesh.ka...@gmail.com
wrote:
I know this has been a while, but was this ever resolved? We're seeing
the
same problem. And, because of this problem, Wicket is never cleaning up
old
session pagemap files which leads to oodles of files in our tomcat work
directory.
Thanks,
Meetesh
On Sat, Nov 22, 2008 at 5:55 AM, Carlos Pita carlosjosep...@gmail.com
wrote:
Matej,
forget what I said yesterday about session lastAccessedDate, I've
debugged it in detail and tomcat is doing its part fine, I was
confused by a sequence of logs that implied that the session was
swapped out before a page was added to its pagemap. But later I found
out that this wasn't the usual pattern so I included more log output
here and there. And now it seems as if the pagemap instance that is
swapped out isn't the same one where the page was first put. Below I
copied the pertinent fragments of code and one example of output
showing the anomaly:
1) What follows is in order to identify each pagemap instance (with
thisNum):
private static final class SecondLevelCachePageMap extends PageMap
{
private static int pageMapNum = 0;
private int thisNum;
private SecondLevelCachePageMap(String sessionId, Application
application, String name)
{
synchronized (SecondLevelCachePageMap.class)
{
thisNum = pageMapNum++;
}
}
2) Now for the logging part
a) First when a page is put into the pagemap
public void put(Page page)
{
if (!page.isPageStateless())
{
Session session = getSession();
String sessionId = session.getId();
if (sessionId != null !session.isSessionInvalidated())
{
// the id could have changed from null during request
this.sessionId = sessionId;
log.error(put + sessionId + + thisNum);
getStore().storePage(sessionId, page);
setLastPage(page);
dirty();
}
}
}
b) Then when a pagemap is swapped out (writeObject):
private void writeObject(java.io.ObjectOutputStream s) throws
IOException
{
s.defaultWriteObject();
IPageStore store = getPageStore();
if (sessionId != null store instanceof IClusteredPageStore == false)
{
-- if (lastPage == null) log.error(writeObject1 + sessionId +
+ thisNum); --
Object page = lastPage;
if (store instanceof ISerializationAwarePageStore)
{
page =
(ISerializationAwarePageStore)store).prepareForSerialization(...
-- if (page == null) log.error(writeObject2 + sessionId + +
thisNum); --
}
}
.
}
Finally, the output looks like:
2008-11-22 04:43:58,841 PAGE 19ACC6B64E22346D494E742A0E859B52 29
other pages in other sessions follows
2008-11-22 04:44:00,486 put 33932E31AE77206B5E556266170B4827 33
2008-11-22 04:44:00,201 put C6423FDD58C4B31C080700E4455F158C
and about 120 secs later:
2008-11-22 04:46:36,432 writeObject1 19ACC6B64E22346D494E742A0E859B52 30
2008-11-22 04:46:36,432 writeObject2 19ACC6B64E22346D494E742A0E859B52 30
In every case I've seen the instance num for the writeObject1/2 logs
was one plus the num for the put log in the same session. I think that
here the second pagemap (30) is created with a default lastPage = null
that never is assigned a non null page, because put is being called on
the first pagemap (29) instead.
I still don't know where the second pagemap is created, but I'm getting
closer.
HIH
-Carlos
On Thu, Nov 20, 2008 at 3:05 AM, Carlos Pita carlosjosep...@gmail.com
wrote:
Hi Matej,
I'm browsing your changes. Please notice that according to my own
debugging it's lastPage itself that is null and not only the result of
prepareForSerialization. So I don't think the warning PageStore
prepared non-null page as null for serialization will ever be
reached. Anyway, I will add other warnings and keep you informed of
the output as soon as I can. This is really tricky to debug because up
til today I'm only able to reproduce it at full scale in a production
environment.
Do you have any idea why a lastPage would be null after 120 secs of
the request that created the session? Specially for sessions that
don't survive that first request. An exception that could avoid
request cycle to detach the session maybe?
Thanks!
-Carlos
On Wed, Nov 19,
Re: null lastPage at restoreAfterSerialization
Matej,
forget what I said yesterday about session lastAccessedDate, I've
debugged it in detail and tomcat is doing its part fine, I was
confused by a sequence of logs that implied that the session was
swapped out before a page was added to its pagemap. But later I found
out that this wasn't the usual pattern so I included more log output
here and there. And now it seems as if the pagemap instance that is
swapped out isn't the same one where the page was first put. Below I
copied the pertinent fragments of code and one example of output
showing the anomaly:
1) What follows is in order to identify each pagemap instance (with thisNum):
private static final class SecondLevelCachePageMap extends PageMap
{
private static int pageMapNum = 0;
private int thisNum;
private SecondLevelCachePageMap(String sessionId, Application
application, String name)
{
synchronized (SecondLevelCachePageMap.class)
{
thisNum = pageMapNum++;
}
}
2) Now for the logging part
a) First when a page is put into the pagemap
public void put(Page page)
{
if (!page.isPageStateless())
{
Session session = getSession();
String sessionId = session.getId();
if (sessionId != null !session.isSessionInvalidated())
{
// the id could have changed from null during request
this.sessionId = sessionId;
log.error(put + sessionId + + thisNum);
getStore().storePage(sessionId, page);
setLastPage(page);
dirty();
}
}
}
b) Then when a pagemap is swapped out (writeObject):
private void writeObject(java.io.ObjectOutputStream s) throws IOException
{
s.defaultWriteObject();
IPageStore store = getPageStore();
if (sessionId != null store instanceof IClusteredPageStore == false)
{
-- if (lastPage == null) log.error(writeObject1 + sessionId +
+ thisNum); --
Object page = lastPage;
if (store instanceof ISerializationAwarePageStore)
{
page = (ISerializationAwarePageStore)store).prepareForSerialization(...
-- if (page == null) log.error(writeObject2 + sessionId + +
thisNum); --
}
}
.
}
Finally, the output looks like:
2008-11-22 04:43:58,841 PAGE 19ACC6B64E22346D494E742A0E859B52 29
other pages in other sessions follows
2008-11-22 04:44:00,486 put 33932E31AE77206B5E556266170B4827 33
2008-11-22 04:44:00,201 put C6423FDD58C4B31C080700E4455F158C
and about 120 secs later:
2008-11-22 04:46:36,432 writeObject1 19ACC6B64E22346D494E742A0E859B52 30
2008-11-22 04:46:36,432 writeObject2 19ACC6B64E22346D494E742A0E859B52 30
In every case I've seen the instance num for the writeObject1/2 logs
was one plus the num for the put log in the same session. I think that
here the second pagemap (30) is created with a default lastPage = null
that never is assigned a non null page, because put is being called on
the first pagemap (29) instead.
I still don't know where the second pagemap is created, but I'm getting closer.
HIH
-Carlos
On Thu, Nov 20, 2008 at 3:05 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Hi Matej,
I'm browsing your changes. Please notice that according to my own
debugging it's lastPage itself that is null and not only the result of
prepareForSerialization. So I don't think the warning PageStore
prepared non-null page as null for serialization will ever be
reached. Anyway, I will add other warnings and keep you informed of
the output as soon as I can. This is really tricky to debug because up
til today I'm only able to reproduce it at full scale in a production
environment.
Do you have any idea why a lastPage would be null after 120 secs of
the request that created the session? Specially for sessions that
don't survive that first request. An exception that could avoid
request cycle to detach the session maybe?
Thanks!
-Carlos
On Wed, Nov 19, 2008 at 7:18 PM, Matej Knopp [EMAIL PROTECTED] wrote:
This really is weird. I added couple of warnings and null check to 1.4
trunk. I wonder if that helps it though.
-Matej
On Wed, Nov 19, 2008 at 12:44 PM, Carlos Pita [EMAIL PROTECTED] wrote:
The last one of the saga for now, I badly need to sleep.
I've been sampling tomcat work dir every second:
i=0; while [[ i -le 300 ]]; do echo $i; ls -lt /u01/tomcatWork/_
/tmp/work$i; sleep 1; i=$((i + 1)); done
Then I greped a number of session ids corresponding to
restoreAfterSerialization errors and every one of them appears in zero
or one samples at most. With maxIdleTime = 120 secs the pattern is
this:
/u01/tomcatWork/_/wicketServlet-fileStore/sessionid created at
T - 120 secs
/u01/tomcatWork/_/sessionid.session
swapped out at T - serialized
restoreAfterSerialization error
expired at ~T - deserialized
The life span of /u01/tomcatWork/_/sessionid.session is of a
fraction of a second. So the problem seems to be definitely related to
short lived sessions that are removed immediately after being swapped
out. The session is removed sooner than expected because of the
exception that is thrown attempting to deserialize the lastPage. This
is clear
Re: null lastPage at restoreAfterSerialization
Another fact that could be relevant is that this only happens upon
processexpires, but never for swapin, which seems to suggest that the
span of the sessions that fail to restore is just one request (maybe
the ones coming from bots that don't support cookies).
Best regards
-Carlos
On Wed, Nov 19, 2008 at 7:13 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Hi all,
as I've a requirement to maintain long lived sessions (~120s) I'm
using tomcat's PersistentManager to avoid keeping lots of sessions in
memory, each one with its own lastPage. I'm observing, specially in a
heavy loaded production environment, permanent errors with a trace
like
Nov 19, 2008 1:56:20 AM org.apache.catalina.session.StoreBase processExpires
SEVERE: Session: 115F3CD5A33E7D941AF8971FA62DE270;
java.lang.IllegalArgumentException: Unknown object type null
at
org.apache.wicket.protocol.http.pagestore.DiskPageStore.restoreAfterSerialization(DiskPageStore.java:1214)
at
org.apache.wicket.protocol.http.SecondLevelCacheSessionStore$SecondLevelCachePageMap.readObject(SecondLevelCacheSessionStore.java:409)
at sun.reflect.GeneratedMethodAccessor85.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974)
at
java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1849)
at
java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1753)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
at
org.apache.catalina.session.StandardSession.readObject(StandardSession.java:1441)
at
org.apache.catalina.session.StandardSession.readObjectData(StandardSession.java:942)
at org.apache.catalina.session.FileStore.load(FileStore.java:296)
at
org.apache.catalina.session.StoreBase.processExpires(StoreBase.java:195)
at
org.apache.catalina.session.PersistentManagerBase.processExpires(PersistentManagerBase.java:553)
at
org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:667)
I've managed myself to reproduced this error in a more controlled
environment and I discovered that tomcat's manager background thread
is swapping out the
session at a moment where lastPage == null.
SecondLevelCacheSessionStore$SecondLevelCachePageMap [line: 380]
if (sessionId != null store instanceof IClusteredPageStore == false)
{
Object page = lastPage;
if (store instanceof
ISerializationAwarePageStore)---
conditional breakpoint if page == null
{
Daemon Thread [ContainerBackgroundProcessor[StandardEngine[Catalina]]]
(Suspended (breakpoint at line 380 in
SecondLevelCacheSessionStore$SecondLevelCachePageMap))
SecondLevelCacheSessionStore$SecondLevelCachePageMap.writeObject(ObjectOutputStream)
line: 380
GeneratedMethodAccessor139.invoke(Object, Object[]) line: not available
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25
Method.invoke(Object, Object...) line: 597
ObjectStreamClass.invokeWriteObject(Object, ObjectOutputStream) line:
945
ObjectOutputStream.writeSerialData(Object, ObjectStreamClass) line:
1461
ObjectOutputStream.writeOrdinaryObject(Object, ObjectStreamClass,
boolean) line: 1392
ObjectOutputStream.writeObject0(Object, boolean) line: 1150
ObjectOutputStream.writeObject(Object) line: 326
StandardSession.writeObject(ObjectOutputStream) line: 1517
StandardSession.writeObjectData(ObjectOutputStream) line: 959
FileStore.save(Session) line: 372
PersistentManager(PersistentManagerBase).writeSession(Session) line:
868
PersistentManager(PersistentManagerBase).swapOut(Session) line: 839
PersistentManager(PersistentManagerBase).processMaxIdleSwaps() line:
1058
PersistentManager(PersistentManagerBase).processPersistenceChecks()
line: 570
PersistentManager(PersistentManagerBase).processExpires() line: 551
PersistentManager(ManagerBase).backgroundProcess() line: 667
StandardContext(ContainerBase).backgroundProcess() line: 1316
ContainerBase$ContainerBackgroundProcessor.processChildren(Container,
ClassLoader) line: 1601
ContainerBase$ContainerBackgroundProcessor.processChildren(Container,
ClassLoader) line: 1610
ContainerBase$ContainerBackgroundProcessor.processChildren(Container,
ClassLoader) line: 1610
ContainerBase$ContainerBackgroundProcessor.run() line: 1590
Thread.run() line: 619
I've configured a minIdleTime of 120 seconds so I don't think tomcat
swaps the session out
Re: null lastPage at restoreAfterSerialization
The last one of the saga for now, I badly need to sleep.
I've been sampling tomcat work dir every second:
i=0; while [[ i -le 300 ]]; do echo $i; ls -lt /u01/tomcatWork/_
/tmp/work$i; sleep 1; i=$((i + 1)); done
Then I greped a number of session ids corresponding to
restoreAfterSerialization errors and every one of them appears in zero
or one samples at most. With maxIdleTime = 120 secs the pattern is
this:
/u01/tomcatWork/_/wicketServlet-fileStore/sessionid created at
T - 120 secs
/u01/tomcatWork/_/sessionid.session
swapped out at T - serialized
restoreAfterSerialization error
expired at ~T - deserialized
The life span of /u01/tomcatWork/_/sessionid.session is of a
fraction of a second. So the problem seems to be definitely related to
short lived sessions that are removed immediately after being swapped
out. The session is removed sooner than expected because of the
exception that is thrown attempting to deserialize the lastPage. This
is clear from inspection of tomcat's StoreBase.processExpires:
try {
StandardSession session = (StandardSession) load(keys[i]);
-- load fails
.
if (session.isValid()) {
continue; -- ideally we should be here
}
.
remove(session.getIdInternal());
} catch (Exception e) {
.
remove(keys[i]); -- but instead
/u01/tomcatWork/_/sessionid.session is prematurely removed here
}
HIH
-Carlos
On Wed, Nov 19, 2008 at 7:34 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Another fact that could be relevant is that this only happens upon
processexpires, but never for swapin, which seems to suggest that the
span of the sessions that fail to restore is just one request (maybe
the ones coming from bots that don't support cookies).
Best regards
-Carlos
On Wed, Nov 19, 2008 at 7:13 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Hi all,
as I've a requirement to maintain long lived sessions (~120s) I'm
using tomcat's PersistentManager to avoid keeping lots of sessions in
memory, each one with its own lastPage. I'm observing, specially in a
heavy loaded production environment, permanent errors with a trace
like
Nov 19, 2008 1:56:20 AM org.apache.catalina.session.StoreBase processExpires
SEVERE: Session: 115F3CD5A33E7D941AF8971FA62DE270;
java.lang.IllegalArgumentException: Unknown object type null
at
org.apache.wicket.protocol.http.pagestore.DiskPageStore.restoreAfterSerialization(DiskPageStore.java:1214)
at
org.apache.wicket.protocol.http.SecondLevelCacheSessionStore$SecondLevelCachePageMap.readObject(SecondLevelCacheSessionStore.java:409)
at sun.reflect.GeneratedMethodAccessor85.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974)
at
java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1849)
at
java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1753)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
at
org.apache.catalina.session.StandardSession.readObject(StandardSession.java:1441)
at
org.apache.catalina.session.StandardSession.readObjectData(StandardSession.java:942)
at org.apache.catalina.session.FileStore.load(FileStore.java:296)
at
org.apache.catalina.session.StoreBase.processExpires(StoreBase.java:195)
at
org.apache.catalina.session.PersistentManagerBase.processExpires(PersistentManagerBase.java:553)
at
org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:667)
I've managed myself to reproduced this error in a more controlled
environment and I discovered that tomcat's manager background thread
is swapping out the
session at a moment where lastPage == null.
SecondLevelCacheSessionStore$SecondLevelCachePageMap [line: 380]
if (sessionId != null store instanceof IClusteredPageStore ==
false)
{
Object page = lastPage;
if (store instanceof
ISerializationAwarePageStore)---
conditional breakpoint if page == null
{
Daemon Thread [ContainerBackgroundProcessor[StandardEngine[Catalina]]]
(Suspended (breakpoint at line 380 in
SecondLevelCacheSessionStore$SecondLevelCachePageMap))
SecondLevelCacheSessionStore$SecondLevelCachePageMap.writeObject(ObjectOutputStream)
line: 380
GeneratedMethodAccessor139.invoke(Object, Object[]) line: not
available
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25
Method.invoke(Object, Object...) line: 597
ObjectStreamClass.invokeWriteObject(Object,
Re: null lastPage at restoreAfterSerialization
This really is weird. I added couple of warnings and null check to 1.4
trunk. I wonder if that helps it though.
-Matej
On Wed, Nov 19, 2008 at 12:44 PM, Carlos Pita [EMAIL PROTECTED] wrote:
The last one of the saga for now, I badly need to sleep.
I've been sampling tomcat work dir every second:
i=0; while [[ i -le 300 ]]; do echo $i; ls -lt /u01/tomcatWork/_
/tmp/work$i; sleep 1; i=$((i + 1)); done
Then I greped a number of session ids corresponding to
restoreAfterSerialization errors and every one of them appears in zero
or one samples at most. With maxIdleTime = 120 secs the pattern is
this:
/u01/tomcatWork/_/wicketServlet-fileStore/sessionid created at
T - 120 secs
/u01/tomcatWork/_/sessionid.session
swapped out at T - serialized
restoreAfterSerialization error
expired at ~T - deserialized
The life span of /u01/tomcatWork/_/sessionid.session is of a
fraction of a second. So the problem seems to be definitely related to
short lived sessions that are removed immediately after being swapped
out. The session is removed sooner than expected because of the
exception that is thrown attempting to deserialize the lastPage. This
is clear from inspection of tomcat's StoreBase.processExpires:
try {
StandardSession session = (StandardSession) load(keys[i]);
-- load fails
.
if (session.isValid()) {
continue; -- ideally we should be here
}
.
remove(session.getIdInternal());
} catch (Exception e) {
.
remove(keys[i]); -- but instead
/u01/tomcatWork/_/sessionid.session is prematurely removed here
}
HIH
-Carlos
On Wed, Nov 19, 2008 at 7:34 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Another fact that could be relevant is that this only happens upon
processexpires, but never for swapin, which seems to suggest that the
span of the sessions that fail to restore is just one request (maybe
the ones coming from bots that don't support cookies).
Best regards
-Carlos
On Wed, Nov 19, 2008 at 7:13 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Hi all,
as I've a requirement to maintain long lived sessions (~120s) I'm
using tomcat's PersistentManager to avoid keeping lots of sessions in
memory, each one with its own lastPage. I'm observing, specially in a
heavy loaded production environment, permanent errors with a trace
like
Nov 19, 2008 1:56:20 AM org.apache.catalina.session.StoreBase processExpires
SEVERE: Session: 115F3CD5A33E7D941AF8971FA62DE270;
java.lang.IllegalArgumentException: Unknown object type null
at
org.apache.wicket.protocol.http.pagestore.DiskPageStore.restoreAfterSerialization(DiskPageStore.java:1214)
at
org.apache.wicket.protocol.http.SecondLevelCacheSessionStore$SecondLevelCachePageMap.readObject(SecondLevelCacheSessionStore.java:409)
at sun.reflect.GeneratedMethodAccessor85.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974)
at
java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1849)
at
java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1753)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
at
org.apache.catalina.session.StandardSession.readObject(StandardSession.java:1441)
at
org.apache.catalina.session.StandardSession.readObjectData(StandardSession.java:942)
at org.apache.catalina.session.FileStore.load(FileStore.java:296)
at
org.apache.catalina.session.StoreBase.processExpires(StoreBase.java:195)
at
org.apache.catalina.session.PersistentManagerBase.processExpires(PersistentManagerBase.java:553)
at
org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:667)
I've managed myself to reproduced this error in a more controlled
environment and I discovered that tomcat's manager background thread
is swapping out the
session at a moment where lastPage == null.
SecondLevelCacheSessionStore$SecondLevelCachePageMap [line: 380]
if (sessionId != null store instanceof IClusteredPageStore ==
false)
{
Object page = lastPage;
if (store instanceof
ISerializationAwarePageStore)---
conditional breakpoint if page == null
{
Daemon Thread [ContainerBackgroundProcessor[StandardEngine[Catalina]]]
(Suspended (breakpoint at line 380 in
SecondLevelCacheSessionStore$SecondLevelCachePageMap))
SecondLevelCacheSessionStore$SecondLevelCachePageMap.writeObject(ObjectOutputStream)
line: 380
Re: null lastPage at restoreAfterSerialization
Hi Matej,
I'm browsing your changes. Please notice that according to my own
debugging it's lastPage itself that is null and not only the result of
prepareForSerialization. So I don't think the warning PageStore
prepared non-null page as null for serialization will ever be
reached. Anyway, I will add other warnings and keep you informed of
the output as soon as I can. This is really tricky to debug because up
til today I'm only able to reproduce it at full scale in a production
environment.
Do you have any idea why a lastPage would be null after 120 secs of
the request that created the session? Specially for sessions that
don't survive that first request. An exception that could avoid
request cycle to detach the session maybe?
Thanks!
-Carlos
On Wed, Nov 19, 2008 at 7:18 PM, Matej Knopp [EMAIL PROTECTED] wrote:
This really is weird. I added couple of warnings and null check to 1.4
trunk. I wonder if that helps it though.
-Matej
On Wed, Nov 19, 2008 at 12:44 PM, Carlos Pita [EMAIL PROTECTED] wrote:
The last one of the saga for now, I badly need to sleep.
I've been sampling tomcat work dir every second:
i=0; while [[ i -le 300 ]]; do echo $i; ls -lt /u01/tomcatWork/_
/tmp/work$i; sleep 1; i=$((i + 1)); done
Then I greped a number of session ids corresponding to
restoreAfterSerialization errors and every one of them appears in zero
or one samples at most. With maxIdleTime = 120 secs the pattern is
this:
/u01/tomcatWork/_/wicketServlet-fileStore/sessionid created at
T - 120 secs
/u01/tomcatWork/_/sessionid.session
swapped out at T - serialized
restoreAfterSerialization error
expired at ~T - deserialized
The life span of /u01/tomcatWork/_/sessionid.session is of a
fraction of a second. So the problem seems to be definitely related to
short lived sessions that are removed immediately after being swapped
out. The session is removed sooner than expected because of the
exception that is thrown attempting to deserialize the lastPage. This
is clear from inspection of tomcat's StoreBase.processExpires:
try {
StandardSession session = (StandardSession) load(keys[i]);
-- load fails
.
if (session.isValid()) {
continue; -- ideally we should be here
}
.
remove(session.getIdInternal());
} catch (Exception e) {
.
remove(keys[i]); -- but instead
/u01/tomcatWork/_/sessionid.session is prematurely removed here
}
HIH
-Carlos
On Wed, Nov 19, 2008 at 7:34 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Another fact that could be relevant is that this only happens upon
processexpires, but never for swapin, which seems to suggest that the
span of the sessions that fail to restore is just one request (maybe
the ones coming from bots that don't support cookies).
Best regards
-Carlos
On Wed, Nov 19, 2008 at 7:13 AM, Carlos Pita [EMAIL PROTECTED] wrote:
Hi all,
as I've a requirement to maintain long lived sessions (~120s) I'm
using tomcat's PersistentManager to avoid keeping lots of sessions in
memory, each one with its own lastPage. I'm observing, specially in a
heavy loaded production environment, permanent errors with a trace
like
Nov 19, 2008 1:56:20 AM org.apache.catalina.session.StoreBase
processExpires
SEVERE: Session: 115F3CD5A33E7D941AF8971FA62DE270;
java.lang.IllegalArgumentException: Unknown object type null
at
org.apache.wicket.protocol.http.pagestore.DiskPageStore.restoreAfterSerialization(DiskPageStore.java:1214)
at
org.apache.wicket.protocol.http.SecondLevelCacheSessionStore$SecondLevelCachePageMap.readObject(SecondLevelCacheSessionStore.java:409)
at sun.reflect.GeneratedMethodAccessor85.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:974)
at
java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1849)
at
java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1753)
at
java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1329)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:351)
at
org.apache.catalina.session.StandardSession.readObject(StandardSession.java:1441)
at
org.apache.catalina.session.StandardSession.readObjectData(StandardSession.java:942)
at org.apache.catalina.session.FileStore.load(FileStore.java:296)
at
org.apache.catalina.session.StoreBase.processExpires(StoreBase.java:195)
at
org.apache.catalina.session.PersistentManagerBase.processExpires(PersistentManagerBase.java:553)
at
org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:667)
I've managed myself to reproduced this error in a more controlled
environment and I
