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, 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 while it's still being accessed, in an invalid
>> intermediate state. The code for processMaxIdleSwaps looks fine:
>>
>> protected void processMaxIdleSwaps() {
>>
>> if (!isStarted() || maxIdleSwap < 0)
>> return;
>>
>> Session sessions[] = findSessions();
>> long timeNow = System.currentTimeMillis();
>>
>> // Swap out all sessions idle longer than maxIdleSwap
>> if (maxIdleSwap >= 0) {
>> for (int i = 0; i < sessions.length; i++) {
>> StandardSession session = (StandardSession) sessions[i];
>> synchronized (session) {
>> if (!session.isValid())
>> continue;
>> int timeIdle = // Truncate, do not round up
>> (int) ((timeNow -
>> session.getLastAccessedTime()) / 1000L);
>> if (timeIdle > maxIdleSwap && timeIdle > minIdleSwap) {
>> if (log.isDebugEnabled())
>> log.debug(sm.getString
>> ("persistentManager.swapMaxIdle",
>> session.getIdInternal(), new
>> Integer(timeIdle)));
>> try {
>> swapOut(session);
>> } catch (IOException e) {
>> ; // This is logged in writeSession()
>> }
>> }
>> }
>> }
>> }
>>
>> }
>>
>> Do you have any idea why lastPage could be null so many times (as an
>> important percentage -about 10%- of the sessions throws the above
>> error) ? Take into account that a big number of bots and crawlers is
>> accessing the site.
>>
>> Any help will be very appreciated, I've spent many hours and days
>> tracing this issue...
>>
>> Best regards
>> -Carlos
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
