Log4J: FATAL ngoại lệ trên shutdown hook, không thể tìm ra lý do tại sao

Question

Tôi chỉ tích hợp log4j vào ứng dụng của mình, và tôi thiết lập AspectJ để sử dụng log4j và cuối cùng chuyển tất cả đăng xuất khỏi mã chính của mình. Vì vậy, trong ngắn hạn, tôi đang thiết lập các khía cạnh thực hiện các mục nhật ký, và sau đó chạy chương trình của tôi trong một thời gian ngắn để kiểm tra chúng.

Thông thường, trong những lần chạy ngắn, tôi nhận được ngoại lệ sau đây:

2015-09-28 15:21:48,222 Thread-4 FATAL Unable to register shutdown hook because JVM is shutting down. java.lang.IllegalStateException: Cannot add new shutdown hook as this is not started. Current state: STOPPED 
at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:113) 
at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:271) 
at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:240) 
at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:201) 
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:233) 
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41) 
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:162) 
at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:507) 
at org.jboss.logging.Log4j2Logger.<init>(Log4j2Logger.java:36) 
at org.jboss.logging.Log4j2LoggerProvider.getLogger(Log4j2LoggerProvider.java:30) 
at org.jboss.logging.Log4j2LoggerProvider.getLogger(Log4j2LoggerProvider.java:26) 
at org.jboss.logging.Logger.getLogger(Logger.java:2465) 
at org.jboss.logging.Logger$1.run(Logger.java:2565) 
at java.security.AccessController.doPrivileged(Native Method) 
at org.jboss.logging.Logger.getMessageLogger(Logger.java:2529) 
at org.jboss.logging.Logger.getMessageLogger(Logger.java:2516) 
at org.hibernate.internal.CoreLogging.messageLogger(CoreLogging.java:28) 
at org.hibernate.internal.CoreLogging.messageLogger(CoreLogging.java:24) 
at org.hibernate.event.internal.ReattachVisitor.<clinit>(ReattachVisitor.java:27) 
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.performUpdate(DefaultSaveOrUpdateEventListener.java:293) 
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:227) 
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.performSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:92) 
at org.hibernate.event.internal.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:73) 
at org.hibernate.internal.SessionImpl.fireSaveOrUpdate(SessionImpl.java:647) 
at org.hibernate.internal.SessionImpl.saveOrUpdate(SessionImpl.java:639) 
at org.hibernate.internal.SessionImpl.saveOrUpdate(SessionImpl.java:634) 
at io.craigmiller160.stockmarket.controller.HibernatePortfolioDAO.savePortfolio(HibernatePortfolioDAO.java:225) 
at io.craigmiller160.stockmarket.controller.StockMarketController.savePortfolio(StockMarketController.java:1441) 
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
at java.lang.reflect.Method.invoke(Method.java:497) 
at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:353) 
at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:276) 
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578) 
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554) 
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:925) 
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523) 
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:932) 
at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:997) 
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:973) 
at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:893) 

thoảng, nhưng không phải lúc nào, ngoại lệ này là trước bởi:

2015-09-28 15:21:48,152 Thread-4 ERROR An exception occurred processing Appender asyncAppender java.lang.IllegalStateException: AsyncAppender asyncAppender is not active 
at org.apache.logging.log4j.core.appender.AsyncAppender.append(AsyncAppender.java:136) 
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:148) 
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:121) 
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:112) 
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:80) 
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390) 
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378) 
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362) 
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:352) 
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:59) 
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:138) 
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:999) 
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:954) 
at org.apache.logging.log4j.jcl.Log4jLog.debug(Log4jLog.java:81) 
at org.springframework.jdbc.datasource.DriverManagerDataSource.getConnectionFromDriver(DriverManagerDataSource.java:142) 
at org.springframework.jdbc.datasource.AbstractDriverBasedDataSource.getConnectionFromDriver(AbstractDriverBasedDataSource.java:155) 
at org.springframework.jdbc.datasource.AbstractDriverBasedDataSource.getConnection(AbstractDriverBasedDataSource.java:120) 
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) 
at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:382) 
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87) 
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:112) 
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:230) 
at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:237) 
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:213) 
at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:52) 
at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1443) 
at io.craigmiller160.stockmarket.controller.HibernatePortfolioDAO.savePortfolio(HibernatePortfolioDAO.java:224) 
at io.craigmiller160.stockmarket.controller.StockMarketController.savePortfolio(StockMarketController.java:1441) 
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
at java.lang.reflect.Method.invoke(Method.java:497) 
at org.springframework.beans.factory.support.DisposableBeanAdapter.invokeCustomDestroyMethod(DisposableBeanAdapter.java:353) 
at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:276) 
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578) 
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554) 
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:925) 
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523) 
at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:932) 
at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:997) 
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:973) 
at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:893) 

Hãy cho tôi biết nếu bạn cần phải nhìn thấy bất cứ điều gì khác để xác định nguyên nhân của việc này. Nó không phải luôn luôn xảy ra, nhưng nó xảy ra khá thường xuyên khi chương trình được chạy chỉ trong 10-20 giây. Tôi chỉ không hiểu tại sao điều này lại xảy ra.

Answer 1

Log4j2 cố gắng sử dụng shutdown hook để đóng dịch vụ ghi nhật ký chính xác.

Móc tắt máy được thực hiện song song và đó là lý do ngoại lệ không có hệ thống.

Có một số bug report liên quan đến vấn đề này.

Bạn có thể vô hiệu hóa móc shutdown trong tập tin cấu hình của bạn:

<configuration shutdownHook="disable" ...> 

Answer 2

Cũng xem liên kết này trên trang log4j2 của:

https://logging.apache.org/log4j/2.x/manual/webapp.html

Nếu bạn bao gồm sự phụ thuộc này, nó sẽ không cố gắng thêm một cái móc tắt máy.

<dependency> 
     <groupId>org.apache.logging.log4j</groupId> 
     <artifactId>log4j-web</artifactId> 
     <version>${log4j.version}</version> 
</dependency> 

Answer 3

Đây là vấn đề đã biết. Log4j bây giờ sẽ sử dụng SimpleLogger trong khi tắt máy. Vui lòng xem https://issues.apache.org/jira/browse/LOG4J2-1222.

Answer 4

Như đã đề cập ở đây log4j-web là bình chứa cho vấn đề này. Nó hoạt động mà không có bất kỳ vấn đề cho jetty-9.2.1.v20140609.

libraryDependencies += "org.apache.logging.log4j" % "log4j-web" % "2.5" 

Nếu bạn đánh dấu vào log4j-web, nó có log4j.shutdownHookEnabled=false

Nhưng với Servlet 3.0 và Tomcat 7.0.73, đã phải gỡ bỏ log4j từ jarsToSkip chủ chốt của conf/catalina.properties.

Điều kỳ lạ có thể xảy ra. Đối với tôi, tôi đang triển khai hai .war s, cả hai đều sử dụng Non blocking Logger, làm việc cho một dịch vụ nhưng không phải cho một dịch vụ khác. Tomcat 7/Websphere 8 khởi động lại làm sạch nó mặc dù.

Lý do cần phải clean up logging resource được mô tả trong Using Log4j 2 in Web Applications -

khi Servlet Container tắt hoặc ứng dụng web là undeployed, Điều quan trọng đối với tài nguyên khai thác gỗ phải được làm sạch đúng cách (kết nối cơ sở dữ liệu đóng cửa, các file đã đóng, v.v.)

Do tính chất của ClassLoader trong các ứng dụng web, tài nguyên Log4j không thể là được dọn sạch thông qua các phương tiện thông thường. Log4j phải được "khởi động" khi ứng dụng web triển khai và "tắt" khi ứng dụng web không có hiệu lực.

Vui lòng đọc số official doc - Using Log4j 2 in Web Containers này, hữu ích.