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]
