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 <[email protected]> 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 <[email protected]> > 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 <[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] > >> > >> > > >
