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]