NotSerializableException in JBossCache with Log4J Level clas

[marlig]

Hi,

I'm wondering whether someone has had this problem before, because I couldn't find anything about it in the forums. From time to time in my logs I see this exception:

2006-11-22 17:19:21,104 ERROR [org.jboss.web.tomcat.tc5.session.JBossCacheService] externalizeSession(): exception occurred externalizing session SessionBasedClusteredSession[id: POpO-xNbPcMuoMCfHsgI2w**.node01 lastAccessedTime: 1164212361095 version: 27 lastOutdated: 0]
java.io.NotSerializableException: org.apache.log4j.Level
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1081)
 at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1375)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1347)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1290)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1079)
 at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1375)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1347)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1290)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1079)
 at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1375)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1347)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1290)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1079)
 at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:302)
 at java.util.HashSet.writeObject(HashSet.java:254)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:917)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1339)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1290)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1079)
 at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:302)
 at java.util.HashMap.writeObject(HashMap.java:1039)
 at sun.reflect.GeneratedMethodAccessor134.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:917)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1339)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1290)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1079)
 at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:302)
 at java.util.Hashtable.writeObject(Hashtable.java:813)
 at sun.reflect.GeneratedMethodAccessor342.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:917)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1339)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1290)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1079)
 at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:302)
 at org.jboss.web.tomcat.tc5.session.SessionBasedClusteredSession.writeExternal(SessionBasedClusteredSession.java:175)
 at org.jboss.web.tomcat.tc5.session.JBossCacheService.externalizeSession(JBossCacheService.java:902)
 at org.jboss.web.tomcat.tc5.session.JBossCacheService.putSession(JBossCacheService.java:348)
 at org.jboss.web.tomcat.tc5.session.JBossCacheClusteredSession.processSessionRepl(JBossCacheClusteredSession.java:122)
 at org.jboss.web.tomcat.tc5.session.JBossCacheManager.processSessionRepl(JBossCacheManager.java:994)
 at org.jboss.web.tomcat.tc5.session.JBossCacheManager.storeSession(JBossCacheManager.java:637)
 at org.jboss.web.tomcat.tc5.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:52)
 at org.jboss.web.tomcat.tc5.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:105)
 at org.jboss.web.tomcat.tc5.session.JvmRouteValve.invoke(JvmRouteValve.java:84)
 at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:432)
 at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:74)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
 at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:199)
 at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:282)
 at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:754)
 at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:684)
 at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:876)
 at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
 at java.lang.Thread.run(Thread.java:595)

What I was able to find somewhere was a bug in Log4J saying the Level class is not serializable. Now I thought I would just replace the Log4J version that ships with JBoss 4.0.4 with a newer version (Log4J 1.2.13), but somehow the problem persists.

What I replaced were the log4j.jar in server/all/lib, but not the log4j-boot.jar in the servers lib directory. I guess these are the classes that are still loaded first, and thus still causing the problem. But I am not sure on how to replace this log4j-boot.jar (if it's the source of the problem at all)? Could I just replace it with the normal log4j.jar?

Thanks for your help and ideas
Martin

[hmesha]

You probably have an object in your application trying to store org.apache.log4j.Level instance in the session and that's why you're seeing the stack trace below.

[marlig]

I couldn't find a place where we would directly insert the Level class into the Session. Though this probably doesn't mean we don't do it indirectly somewhere.

However, I replaced log4j-boot.jar in JBoss with my own version, and so far the problem has not shown again in the logs. Time will show whether this was the solution or not.

Martin

[pledge]

Did you find if this was the solution? I am getting the same problem but with Logger rather than Level. I have made a log4j-boot based on log4j 1.2.13 but I still get a doezen replication errors on every page load.

Thanks.

[marlig]

I'm afraid the problem still exists. However, it was hidden for a while behind another serialization problem regarding java.lang.reflect.Method. Seems we/some of the frameworks we use are putting this into the Session. After searching for quite a long time I kind of gave up and just removed the exception from the log files by setting the log level to fatal. Not a very honorable thing to do, but I found that session replication and failover seems to work despite the problem, and that's what counts for me most.

Regards
Martin

[realstaple]

Any further word on this?

I created a listener that implements both HttpSessionAttributeListener and ServletContextAttributeListener (code below). It exposed a few other classes we were putting into the session.

However, I continue to get the log4j NonSerializable exceptions without any indication from the listener that something has been added that contains org.apache.log4j.Level.

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

import javax.servlet.http.HttpSessionAttributeListener;
import javax.servlet.http.HttpSessionBindingEvent;
import javax.servlet.ServletContextAttributeListener;
import javax.servlet.ServletContextAttributeEvent;
import java.io.ObjectOutputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;

public class FindNonSerializableSessionAttributesListener implements HttpSessionAttributeListener, ServletContextAttributeListener {
private static final Log logger = LogFactory.getLog(FindNonSerializableSessionAttributesListener.class);

public void attributeAdded(HttpSessionBindingEvent httpSessionBindingEvent) {
checkSerailizable(httpSessionBindingEvent.getName(), httpSessionBindingEvent.getValue());
}

public void attributeRemoved(HttpSessionBindingEvent httpSessionBindingEvent) {}

public void attributeReplaced(HttpSessionBindingEvent httpSessionBindingEvent) {
checkSerailizable(httpSessionBindingEvent.getName(), httpSessionBindingEvent.getValue());
}

private void checkSerailizable(String name, Object value) {
if (logger.isDebugEnabled()) {
try {
ObjectOutputStream out = new ObjectOutputStream(new ByteArrayOutputStream());
out.writeObject(value);
out.close();
out.flush();
} catch (IOException e) {
logger.info("Error serialiazing when setting session attribute " + name + "::" + value, e);
}
}
}

public void attributeAdded(ServletContextAttributeEvent servletContextAttributeEvent) {
checkSerailizable(servletContextAttributeEvent.getName(), servletContextAttributeEvent.getValue());
}

public void attributeRemoved(ServletContextAttributeEvent servletContextAttributeEvent) {
//To change body of implemented methods use File | Settings | File Templates.
}

public void attributeReplaced(ServletContextAttributeEvent servletContextAttributeEvent) {
checkSerailizable(servletContextAttributeEvent.getName(), servletContextAttributeEvent.getValue());
}
}