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
>>> 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]
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
