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