Created attachment 758002 [details] reproducer Steps to Reproduce: 1. Set JBOSS_HOME to EAP 6.1.0 2. Unzip attached zip reproducer 3. Run "mvn clean verify -Darquillian=jbossas-managed-7" This test deploys application and starts interval EJB Timer. Then is application undeployed (so the timer is still running). Following exception is not always reproducible (little bit weird, but appears not be timer interval settings dependant), but occurs quite often. 08:29:32,727 ERROR [org.jboss.as.ejb3] (EJB default - 3) JBAS014120: Error invoking timeout for timer: [id=7c79cd4d-704f-4719-8d08-bb8b09d984eb timedObjectId=ejbtest.ejbtest.TestTimer auto-timer?:false persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@14859e7e initialExpiration=Fri Jun 07 08:29:22 CEST 2013 intervalDuration(in milli sec)=5000 nextExpiration=Fri Jun 07 08:29:37 CEST 2013 timerState=IN_TIMEOUT: java.lang.RuntimeException: java.lang.IllegalStateException at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:68) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2] at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final-redhat-2.jar:1.1.1.Final-redhat-2] at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:101) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:111) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] at org.jboss.as.ejb3.timerservice.task.TimerTask.callTimeout(TimerTask.java:157) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:132) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_17] at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) [rt.jar:1.7.0_17] at java.util.concurrent.FutureTask.run(FutureTask.java:166) [rt.jar:1.7.0_17] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_17] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_17] at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_17] at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.1.0.Final-redhat-1.jar:2.1.0.Final-redhat-1] Caused by: java.lang.IllegalStateException at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47) [jboss-msc-1.0.4.GA-redhat-1.jar:1.0.4.GA-redhat-1] at org.jboss.as.connector.deployers.ra.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction.teardown(CachedConnectionManagerSetupProcessor.java:105) [jboss-as-connector-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:62) [jboss-as-ejb3-7.2.0.Final-redhat-8.jar:7.2.0.Final-redhat-8] ... 15 more 08:29:32,748 ERROR [stderr] (EJB default - 3) java.util.logging.ErrorManager: 5: Formatting error 08:29:32,751 ERROR [stderr] (EJB default - 3) java.lang.IllegalStateException 08:29:32,752 ERROR [stderr] (EJB default - 3) at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47) 08:29:32,760 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.getTimedObjectId(TimedObjectInvokerImpl.java:106) 08:29:32,758 INFO [org.jboss.as.server.deployment] (MSC service thread 1-6) JBAS015877: Stopped deployment ejbtest.war (runtime-name: ejbtest.war) in 119ms 08:29:32,760 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.timerservice.TimerImpl.toString(TimerImpl.java:615) 08:29:32,762 ERROR [stderr] (EJB default - 3) at java.util.Formatter$FormatSpecifier.printString(Formatter.java:2838) 08:29:32,763 ERROR [stderr] (EJB default - 3) at java.util.Formatter$FormatSpecifier.print(Formatter.java:2718) 08:29:32,764 ERROR [stderr] (EJB default - 3) at java.util.Formatter.format(Formatter.java:2488) 08:29:32,765 ERROR [stderr] (EJB default - 3) at java.util.Formatter.format(Formatter.java:2423) 08:29:32,766 ERROR [stderr] (EJB default - 3) at java.lang.String.format(String.java:2797) 08:29:32,767 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtLogRecord.formatRecord(ExtLogRecord.java:434) 08:29:32,767 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtLogRecord.getFormattedMessage(ExtLogRecord.java:397) 08:29:32,768 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.formatters.Formatters$10.renderRaw(Formatters.java:359) 08:29:32,769 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:151) 08:29:32,770 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:86) 08:29:32,772 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:35) 08:29:32,773 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:49) 08:29:32,774 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76) 08:29:32,775 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:292) 08:29:32,775 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,775 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,776 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,776 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,777 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.Logger.logRaw(Logger.java:721) 08:29:32,777 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.Logger.log(Logger.java:672) 08:29:32,778 ERROR [stderr] (EJB default - 3) at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:50) 08:29:32,778 ERROR [stderr] (EJB default - 3) at org.jboss.logging.Logger.logf(Logger.java:2093) 08:29:32,779 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.EjbLogger_$logger.timerRetried(EjbLogger_$logger.java:486) 08:29:32,779 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:139) 08:29:32,780 ERROR [stderr] (EJB default - 3) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) 08:29:32,780 ERROR [stderr] (EJB default - 3) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) 08:29:32,781 ERROR [stderr] (EJB default - 3) at java.util.concurrent.FutureTask.run(FutureTask.java:166) 08:29:32,783 ERROR [stderr] (EJB default - 3) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 08:29:32,820 ERROR [stderr] (EJB default - 3) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) 08:29:32,821 ERROR [stderr] (EJB default - 3) at java.lang.Thread.run(Thread.java:722) 08:29:32,822 ERROR [stderr] (EJB default - 3) at org.jboss.threads.JBossThread.run(JBossThread.java:122) 08:29:32,823 ERROR [stderr] (EJB default - 3) java.util.logging.ErrorManager: 5: Formatting error 08:29:32,824 ERROR [stderr] (EJB default - 3) java.lang.IllegalStateException 08:29:32,825 ERROR [stderr] (EJB default - 3) at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47) 08:29:32,825 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.getTimedObjectId(TimedObjectInvokerImpl.java:106) 08:29:32,827 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.timerservice.TimerImpl.toString(TimerImpl.java:615) 08:29:32,827 ERROR [stderr] (EJB default - 3) at java.util.Formatter$FormatSpecifier.printString(Formatter.java:2838) 08:29:32,828 ERROR [stderr] (EJB default - 3) at java.util.Formatter$FormatSpecifier.print(Formatter.java:2718) 08:29:32,829 ERROR [stderr] (EJB default - 3) at java.util.Formatter.format(Formatter.java:2488) 08:29:32,829 ERROR [stderr] (EJB default - 3) at java.util.Formatter.format(Formatter.java:2423) 08:29:32,829 ERROR [stderr] (EJB default - 3) at java.lang.String.format(String.java:2797) 08:29:32,829 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtLogRecord.formatRecord(ExtLogRecord.java:434) 08:29:32,830 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtLogRecord.getFormattedMessage(ExtLogRecord.java:397) 08:29:32,830 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.formatters.Formatters$10.renderRaw(Formatters.java:359) 08:29:32,831 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:151) 08:29:32,832 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:86) 08:29:32,834 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:35) 08:29:32,835 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:49) 08:29:32,835 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76) 08:29:32,835 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:292) 08:29:32,836 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,836 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,836 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,836 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300) 08:29:32,836 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.Logger.logRaw(Logger.java:721) 08:29:32,837 ERROR [stderr] (EJB default - 3) at org.jboss.logmanager.Logger.log(Logger.java:672) 08:29:32,837 ERROR [stderr] (EJB default - 3) at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:50) 08:29:32,837 ERROR [stderr] (EJB default - 3) at org.jboss.logging.Logger.logf(Logger.java:2093) 08:29:32,837 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.EjbLogger_$logger.timerRetried(EjbLogger_$logger.java:486) 08:29:32,837 ERROR [stderr] (EJB default - 3) at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:139) 08:29:32,838 ERROR [stderr] (EJB default - 3) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) 08:29:32,838 ERROR [stderr] (EJB default - 3) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) 08:29:32,838 ERROR [stderr] (EJB default - 3) at java.util.concurrent.FutureTask.run(FutureTask.java:166) 08:29:32,838 ERROR [stderr] (EJB default - 3) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 08:29:32,838 ERROR [stderr] (EJB default - 3) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) 08:29:32,838 ERROR [stderr] (EJB default - 3) at java.lang.Thread.run(Thread.java:722) 08:29:32,839 ERROR [stderr] (EJB default - 3) at org.jboss.threads.JBossThread.run(JBossThread.java:122)
As far as I can tell this should already be fixed in 6.2 as part of a fix for a different issue (980920), so this should just need QA to verify it.
As per comment #1 moving this to ON_QA.
I am still facing following exception (on 6.2.0.ER4) quite frequently running the test from attached reproducer: LogManager error of type FORMAT_FAILURE: Formatting error java.lang.IllegalStateException at org.jboss.msc.value.InjectedValue.getValue(InjectedValue.java:47) at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.getTimedObjectId(TimedObjectInvokerImpl.java:106) at org.jboss.as.ejb3.timerservice.TimerImpl.toString(TimerImpl.java:615) at java.util.Formatter$FormatSpecifier.printString(Formatter.java:2838) at java.util.Formatter$FormatSpecifier.print(Formatter.java:2718) at java.util.Formatter.format(Formatter.java:2488) at java.util.Formatter.format(Formatter.java:2423) at java.lang.String.format(String.java:2797) at org.jboss.logmanager.ExtLogRecord.formatRecord(ExtLogRecord.java:434) at org.jboss.logmanager.ExtLogRecord.getFormattedMessage(ExtLogRecord.java:397) at org.jboss.logmanager.formatters.Formatters$10.renderRaw(Formatters.java:568) at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:225) at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:86) at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:35) at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:49) at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:79) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304) at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304) at org.jboss.logmanager.Logger.logRaw(Logger.java:721) at org.jboss.logmanager.Logger.log(Logger.java:672) at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:50) at org.jboss.logging.Logger.logf(Logger.java:2093) at org.jboss.as.ejb3.EjbLogger_$logger.errorInvokeTimeout(EjbLogger_$logger.java:734) at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:137) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask.run(FutureTask.java:262) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) at org.jboss.threads.JBossThread.run(JBossThread.java:122)
I've ran 100 times the test on EAP 6.3.0.ER10 with this command: for i in {1..100}; do mvn clean verify -Darquillian=jbossas-managed-7 > report/log$i; wait $!; done and there occurred: in four cases only the FORMAT_FAILURE in one case both the FORMAT_FAILURE and an ERROR similar to the one with the EJB timer problem: ERROR [org.jboss.as.ejb3] (EJB default - 3) JBAS014120: Error invoking timeout for timer: [id=5f0af9d8-3f16-4b29-8a27-1883ec611b7d timedObjectId=ejbtest.ejbtest.TestTimer auto-timer?:false persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@533f6512 initialExpiration=Thu Jul 17 14:44:50 CEST 2014 intervalDuration(in milli sec)=5000 nextExpiration=Thu Jul 17 14:45:05 CEST 2014 timerState=IN_TIMEOUT: org.jboss.as.ejb3.component.EJBComponentUnavailableException: JBAS014559: Invocation cannot proceed as component is shutting down I've attached two files: log18 - log where is only the FORMAT_FAILURE log86 - log where are both both the FORMAT_FAILURE and EJB ERROR
Created attachment 918705 [details] log18
Created attachment 918706 [details] log86
After looking at the new error I don't think it is possible to fix this without graceful shutdown. This issue does not just affect timers, it can affect any entry point where a request is active while the server is shutting down. The only way to fix this is with graceful shutdown, so the server does not start shutting down till all active requests are done.
Created attachment 919049 [details] Simple patch for logger exception
Based on comment 9, this apparently still happens in 6.3 and thus should be release noted as a known issue. @Stuart/@baranowb: would you mind describing the CCWR for the RN? Thanks.
baranowb, does the patch in comment 14 address both the errors? If there is a way to fix this in EAP 6.4, please clone this issue for 6.4.
@Ron If Im not wrong, this issue will either be closed or face a shift to 6.4(rejection is more probable). Patch just is a simple hack to avoid exception from logger. The actual reason of those two require a graceful shutdown which is considered as a feature for EAP7(if Im not wrong) and I doubt it will be backported to 6, since it's not even ready for EAP7. Patch is just a simple hack to avoid exception being thrown from logger, it does not fix cause, just hides logger exception, which just looks nasty. I'm going to schedule a CI run against this branch to check if it does not break anything, since stuart seems to be occupied by other tasks.
OK, I'll mark this as Target 6.4.0 (based on comment 8) until the decision is made that this is in fact TBD EAP 7. Also, why is this marked [GSS] ?
Ron [GSS] is my bad, I think Ive abused this prefix.
Link relevant JIRA.
BTW, why the needinfo? flag? Isn't the Doctext sufficient enough?
Hacky patch. Im not sure if its even valid.
Jason Greene <jason.greene> updated the status of jira WFLY-1247 to Resolved