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