log4j:ERROR Attempted to append to closed appender named [A1]

[alex matvey]

Hello all

I have some problem with log4j.

I have web-application which worked in glassfish 2.1 and use log4j for logging.

I'm wrote own log4j appender for sending logs to jms queue (activemq).

for configuration log4j i use ServletContextListener.

This working fine, But when I redeploy web-applications I see follows errors, and problem is solved only when I restart the application server.

[#|2010-07-28T12:23:06.424+0300|SEVERE|sun-appserver2.1|javax.enterprise.system.container.web|_ThreadID=30;_ThreadName=httpWorkerThread-24848-1;_RequestID=1204834e-8c2f-4016-8b66-ed20ddf0020f;|WebModule[/documentsportlet]PWC1275: Exception sending context initialized event to listener instance of class org.mind.documents.server.Log4jInit
java.lang.ThreadDeath
	at org.apache.catalina.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1413)
	at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
	at org.mind.logging.wrappers.ActiveMQueueAppender.close(ActiveMQueueAppender.java:70)
	at org.apache.log4j.helpers.AppenderAttachableImpl.removeAllAppenders(AppenderAttachableImpl.java:141)
	at org.apache.log4j.Category.removeAllAppenders(Category.java:891)
	at org.apache.log4j.PropertyConfigurator.parseCategory(PropertyConfigurator.java:638)
	at org.apache.log4j.PropertyConfigurator.configureRootCategory(PropertyConfigurator.java:544)
	at org.apache.log4j.PropertyConfigurator.doConfigure(PropertyConfigurator.java:440)
	at org.apache.log4j.PropertyConfigurator.doConfigure(PropertyConfigurator.java:334)
	at org.apache.log4j.PropertyConfigurator.configure(PropertyConfigurator.java:342)
	at org.mind.documents.server.Log4jInit.contextInitialized(Log4jInit.java:15)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4666)
	at org.apache.catalina.core.StandardContext.start(StandardContext.java:5375)
	at com.sun.enterprise.web.WebModule.start(WebModule.java:353)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:989)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:973)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:704)
	at com.sun.enterprise.web.WebContainer.loadWebModule(WebContainer.java:1645)
	at com.sun.enterprise.web.WebContainer.loadWebModule(WebContainer.java:1250)
	at com.sun.enterprise.server.WebModuleDeployEventListener.moduleDeployed(WebModuleDeployEventListener.java:182)
	at com.sun.enterprise.server.WebModuleDeployEventListener.moduleDeployed(WebModuleDeployEventListener.java:278)
	at com.sun.enterprise.admin.event.AdminEventMulticaster.invokeModuleDeployEventListener(AdminEventMulticaster.java:1005)
	at com.sun.enterprise.admin.event.AdminEventMulticaster.handleModuleDeployEvent(AdminEventMulticaster.java:992)
	at com.sun.enterprise.admin.event.AdminEventMulticaster.processEvent(AdminEventMulticaster.java:470)
	at com.sun.enterprise.admin.event.AdminEventMulticaster.multicastEvent(AdminEventMulticaster.java:182)
	at com.sun.enterprise.admin.server.core.DeploymentNotificationHelper.multicastEvent(DeploymentNotificationHelper.java:308)
	at com.sun.enterprise.deployment.phasing.DeploymentServiceUtils.multicastEvent(DeploymentServiceUtils.java:231)
	at com.sun.enterprise.deployment.phasing.ServerDeploymentTarget.sendStartEvent(ServerDeploymentTarget.java:298)
	at com.sun.enterprise.deployment.phasing.ApplicationStartPhase.runPhase(ApplicationStartPhase.java:132)
	at com.sun.enterprise.deployment.phasing.DeploymentPhase.executePhase(DeploymentPhase.java:108)
	at com.sun.enterprise.deployment.phasing.PEDeploymentService.executePhases(PEDeploymentService.java:966)
	at com.sun.enterprise.deployment.phasing.PEDeploymentService.start(PEDeploymentService.java:609)
	at com.sun.enterprise.deployment.phasing.PEDeploymentService.start(PEDeploymentService.java:653)
	at com.sun.enterprise.admin.mbeans.ApplicationsConfigMBean.start(ApplicationsConfigMBean.java:773)
	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:597)
	at com.sun.enterprise.admin.MBeanHelper.invokeOperationInBean(MBeanHelper.java:390)
	at com.sun.enterprise.admin.MBeanHelper.invokeOperationInBean(MBeanHelper.java:373)
	at com.sun.enterprise.admin.config.BaseConfigMBean.invoke(BaseConfigMBean.java:477)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:836)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761)
	at sun.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at com.sun.enterprise.admin.util.proxy.ProxyClass.invoke(ProxyClass.java:90)
	at $Proxy1.invoke(Unknown Source)
	at com.sun.enterprise.admin.server.core.jmx.SunoneInterceptor.invoke(SunoneInterceptor.java:304)
	at com.sun.enterprise.interceptor.DynamicInterceptor.invoke(DynamicInterceptor.java:174)
	at com.sun.enterprise.admin.jmx.remote.server.callers.InvokeCaller.call(InvokeCaller.java:69)
	at com.sun.enterprise.admin.jmx.remote.server.MBeanServerRequestHandler.handle(MBeanServerRequestHandler.java:155)
	at com.sun.enterprise.admin.jmx.remote.server.servlet.RemoteJmxConnectorServlet.processRequest(RemoteJmxConnectorServlet.java:122)
	at com.sun.enterprise.admin.jmx.remote.server.servlet.RemoteJmxConnectorServlet.doPost(RemoteJmxConnectorServlet.java:193)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:754)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
	at org.apache.catalina.core.ApplicationFilterChain.servletService(ApplicationFilterChain.java:427)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:315)
	at org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:287)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:218)
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:648)
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:593)
	at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:94)
	at com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:98)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:222)
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:648)
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:593)
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:587)
	at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:1096)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:166)
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:648)
	at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:593)
	at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:587)
	at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:1096)
	at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:291)
	at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.invokeAdapter(DefaultProcessorTask.java:666)
	at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.doProcess(DefaultProcessorTask.java:597)
	at com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:871)
	at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:341)
	at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:263)
	at com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:214)
	at com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:265)
	at com.sun.enterprise.web.connector.grizzly.WorkerThreadImpl.run(WorkerThreadImpl.java:116)
|#]

[#|2010-07-28T12:23:06.565+0300|WARNING|sun-appserver2.1|javax.enterprise.system.stream.err|_ThreadID=30;_ThreadName=httpWorkerThread-24848-1;_RequestID=1204834e-8c2f-4016-8b66-ed20ddf0020f;|
log4j:ERROR Attempted to append to closed appender named [A1].|#]

Listener:

public class Log4jInit implements ServletContextListener {

    public void contextInitialized(ServletContextEvent event) {
        String homeDir=event.getServletContext().getRealPath("/");
        File propertiesFile=new File(homeDir,"WEB-INF/log4j.properties");
        PropertyConfigurator.configure(propertiesFile.toString());
    }

    public void contextDestroyed(ServletContextEvent event) {
    }
}

Appender code:

public class ActiveMQueueAppender extends AppenderSkeleton {
	
	private Session session;
	private MessageProducer producer;
	
	private String brokerUrl;
	private String queueName;

	@Override
	public void activateOptions() {
		try {
			ConnectionFactory connectionFactory = new ActiveMQConnectionFactory(brokerUrl);

			Connection connection = connectionFactory.createConnection();
	        connection.start();			
			
	        session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE);
	        
	        Destination destination = session.createQueue(queueName);
	        
	        producer = session.createProducer(destination);
	        
		} catch (Exception e) {
			errorHandler.error( "Error while activating options for appender named " 
							  + "[" + name + "].", e, ErrorCode.GENERIC_FAILURE);
		}
	}

	
	public synchronized void append(LoggingEvent event) {
		if(event instanceof LSLogginEvent) {
			localAppend((LSLogginEvent) event);
		}
	}

	private void localAppend(LSLogginEvent event) {
		try {
			ObjectMessage msg = session.createObjectMessage();
			msg.setObject(event);
			producer.send(msg);
		} catch (Throwable t) {
			activateOptions();
			t.printStackTrace();
		}
	}
	
	public synchronized void close() {
		if (this.closed)
			return;

		this.closed = true;
		LogLog.debug("Closing appender [" + name + "].");

		try {
			if(producer != null) {
				producer.close();
			}
			
			if (session != null) {
				session.close();
			}
		} catch (JMSException e) {
			LogLog.error("Error while closing ActiveMQueueAppender [" + name + "].", e);
		}
		
		producer = null;
		session = null;
		
	}

	public boolean requiresLayout() {
		return false;
	}

	public String getQueueName() {
		return queueName;
	}

	public void setQueueName(String queueName) {
		this.queueName = queueName;
	}

	public String getBrokerUrl() {
		return brokerUrl;
	}

	public void setBrokerUrl(String brokerUrl) {
		this.brokerUrl = brokerUrl;
	}
}

log4j.properties:

log4j.reset=true

log4j.rootLogger=INFO

log4j.logger.LoggingSystem=INFO, A1
log4j.additivity.LoggingSystem=false

log4j.appender.A1=org.mind.logging.wrappers.ActiveMQueueAppender
log4j.appender.A1.brokerUrl=tcp://host:61616
log4j.appender.A1.queueName=LSLogsQueue

log4j.logger.org.apache.activemq=FATAL, A2

log4j.appender.A2=org.apache.log4j.ConsoleAppender
log4j.appender.A2.layout=org.apache.log4j.PatternLayout
log4j.appender.A2.layout.ConversionPattern=%d %-5p %c - %m%n

what could be the problem? any idea?

Thanks advance.

[Martijn Verburg]

Hi Alex and welcome to Javaranch! Hmm ThreadDeath, that's pretty tricky! I'm not 100% sure, but you may want to look at the scope of the variables in your contextInitialised method and also think carefully about whether you need to do any work in your contextDestroyed method..

[alex matvey]

Martijn Verburg, thanks for your response.

I tried call LogManager.shutdown() into contextDestroyed method, but problem not resolved.

If I leave the method close in appender blank then the application redeployed sucessfully.

I think the problem in releasing resources ( connections... ) .