9 Replies Latest reply on Apr 8, 2015 12:21 PM by sam.cackett

    JBoss EAP 6.3.0 - strange behavior while deploying WAR files

    boaglio

      Hi,

       

      We have noticied on some RHEL servers this behavior:

       

      1. shutdown JBoss EAP 6.3 service

      2. put 3 WAR files inside /standalone/deployments/ directory

      3. start JBoss EAP 6.3 service

       

      Everything goes to "deploying..." and then nothing happens until timeout exception cancel all deploys.

       

      Now we use this strategy:

       

      1. shutdown JBoss EAP 6.3 service

      2. start JBoss EAP 6.3 service

      3. put 1st WAR file inside /standalone/deployments/ directory

      4. wait for complete deploy (~20 seconds )

      5. put 2nd WAR file inside /standalone/deployments/ directory

      6. wait for complete deploy (~20 seconds )

      7. put 3rd WAR file inside /standalone/deployments/ directory

      8. wait for complete deploy (~20 seconds )

       

      How can I make the first strategy work ?

        • 1. Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
          wdfink

          What if you deploy all war files with CLI and restart the server, did that work?

           

          If you reproduce the situation could you get a thread dump and see which process hung and where?

          • 2. Re: Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
            boaglio

            Reproducing the situation, after 300 seconds trying to deploy 2 war files, I get :

             

            15:20:20,313 ERROR [org.jboss.as.controller.management-operation] (Controller Boot Thread) JBAS013412: O intervalo ap?s [300] segundos de espera para estabilidade do cont?iner de servi?o. A opera??o ser? revertida. A etapa que primeiro atualizou o cont?iner do servi?o era 'add' no endere?o '[

                ("core-service" => "management"),

                ("management-interface" => "native-interface")

            ]'

             

            And both files remains "app-name.war.isdeploying" .



            • 3. Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
              jaikiran

              This might be a bug somewhere. Can you get us 3-4 thread dump generated at an interval of 5-10 seconds between each, when you deploy all those 3 war files together and when that hang occurs? You can use jstack or other tools to generate a thread dump of that Java process. More details here https://developer.jboss.org/wiki/ThreadDump

              • 4. Re: Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
                boaglio

                I will ask to our devops team to get some trace files.

                 

                This behavior happens only in production, which has some network restrictions. 

                 

                Maybe JBoss is trying to access some URL from Internet and then get a timeout...  if so how can I avoid it ?

                • 5. Re: Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
                  jaikiran

                  Fernando Boaglio wrote:

                   

                   

                   

                  Maybe JBoss is trying to access some URL from Internet and then get a timeout...  if so how can I avoid it ?

                  Since we don't have enough information, it's hard to tell, but I don't think this has to do with accessing some URL from internet.

                  • 6. Re: Re: Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
                    boaglio

                    Hi,

                     

                    Sorry for my late answer.

                     

                    I could get one thread dump and I found 1 deadlock, maybe log4j related.

                     

                    Please take a look... =)

                    • 7. Re: Re: Re: Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
                      jaikiran

                      Yes, it indeed looks like the threads have ended up in a deadlock while trying to log during the webapp context startup:

                       

                      "ServerService Thread Pool -- 60":
                              at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
                              - waiting to lock <0x00000000dd217c00> (a org.apache.log4j.ConsoleAppender)
                              at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
                              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.Logger.logRaw(Logger.java:721)
                              at org.jboss.logmanager.Logger.log(Logger.java:506)
                              at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71)
                              - locked <0x00000000dae57af8> (a java.lang.StringBuilder)
                              at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
                              at org.jboss.stdio.WriterOutputStream.flush(WriterOutputStream.java:164)
                              - locked <0x00000000dae30448> (a sun.nio.cs.US_ASCII$Decoder)
                              at java.io.PrintStream.write(PrintStream.java:482)
                              - locked <0x00000000dade5e90> (a java.io.PrintStream)
                              at org.jboss.stdio.StdioContext$DelegatingPrintStream.write(StdioContext.java:264)
                              at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
                              at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
                              at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
                              at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
                              - locked <0x00000000d227cc28> (a java.io.OutputStreamWriter)
                              at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
                              at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
                              at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
                              at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
                              at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
                              - locked <0x00000000d22253d8> (a org.apache.log4j.ConsoleAppender)
                              at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
                              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.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.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:326)
                              at org.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:70)
                              at org.apache.commons.logging.impl.SLF4JLocationAwareLog.info(SLF4JLocationAwareLog.java:159)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.registerHandlerMethod(AbstractHandlerMethodMapping.java:180)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.detectHandlerMethods(AbstractHandlerMethodMapping.java:147)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.initHandlerMethods(AbstractHandlerMethodMapping.java:108)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.afterPropertiesSet(AbstractHandlerMethodMapping.java:88)
                              at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping.afterPropertiesSet(RequestMappingHandlerMapping.java:126)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1573)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1511)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
                              at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
                              at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
                              - locked <0x00000000ddcd8ba8> (a java.util.concurrent.ConcurrentHashMap)
                              at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:290)
                              at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:191)
                              at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:636)
                              at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:934)
                              at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479)
                              - locked <0x00000000ddc9eed8> (a java.lang.Object)
                              at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:410)
                              at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
                              at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
                              at org.apache.catalina.core.StandardContext.contextListenerStart(StandardContext.java:3339)
                              at org.apache.catalina.core.StandardContext.start(StandardContext.java:3777)
                              - locked <0x00000000ddc9ef60> (a org.apache.catalina.core.StandardContext)
                              at org.jboss.as.web.deployment.WebDeploymentService.doStart(WebDeploymentService.java:161)
                              at org.jboss.as.web.deployment.WebDeploymentService.access$000(WebDeploymentService.java:59)
                              at org.jboss.as.web.deployment.WebDeploymentService$1.run(WebDeploymentService.java:94)
                              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:745)
                              at org.jboss.threads.JBossThread.run(JBossThread.java:122)
                      "ServerService Thread Pool -- 52":
                              at java.io.PrintStream.write(PrintStream.java:479)
                              - waiting to lock <0x00000000dade5e90> (a java.io.PrintStream)
                              at org.jboss.stdio.StdioContext$DelegatingPrintStream.write(StdioContext.java:264)
                              at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
                              at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
                              at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
                              at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
                              - locked <0x00000000dd2c9320> (a java.io.OutputStreamWriter)
                              at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
                              at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
                              at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
                              at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
                              at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
                              - locked <0x00000000dd217c00> (a org.apache.log4j.ConsoleAppender)
                              at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:42)
                              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.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.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:326)
                              at org.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:70)
                              at org.apache.commons.logging.impl.SLF4JLocationAwareLog.info(SLF4JLocationAwareLog.java:159)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.registerHandlerMethod(AbstractHandlerMethodMapping.java:220)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.detectHandlerMethods(AbstractHandlerMethodMapping.java:187)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.initHandlerMethods(AbstractHandlerMethodMapping.java:147)
                              at org.springframework.web.servlet.handler.AbstractHandlerMethodMapping.afterPropertiesSet(AbstractHandlerMethodMapping.java:126)
                              at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping.afterPropertiesSet(RequestMappingHandlerMapping.java:126)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1627)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1564)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:540)
                              at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476)
                              at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:302)
                              at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:229)
                              - locked <0x00000000dd9ca308> (a java.util.concurrent.ConcurrentHashMap)
                              at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:298)
                              at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:193)
                              at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:725)
                              at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:757)
                              at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:480)
                              - locked <0x00000000dd984a30> (a java.lang.Object)
                              at org.springframework.web.servlet.FrameworkServlet.configureAndRefreshWebApplicationContext(FrameworkServlet.java:663)
                              at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:629)
                              at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:677)
                              at org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:548)
                              at org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:489)
                              at org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:136)
                              at javax.servlet.GenericServlet.init(GenericServlet.java:242)
                              at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1194)
                              - locked <0x00000000dd356748> (a org.apache.catalina.core.StandardWrapper)
                              at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1100)
                              - locked <0x00000000dd356748> (a org.apache.catalina.core.StandardWrapper)
                              at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:3591)
                              at org.apache.catalina.core.StandardContext.start(StandardContext.java:3798)
                              - locked <0x00000000dd356838> (a org.apache.catalina.core.StandardContext)
                              at org.jboss.as.web.deployment.WebDeploymentService.doStart(WebDeploymentService.java:161)
                              at org.jboss.as.web.deployment.WebDeploymentService.access$000(WebDeploymentService.java:59)
                              at org.jboss.as.web.deployment.WebDeploymentService$1.run(WebDeploymentService.java:94)
                              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:745)
                              at org.jboss.threads.JBossThread.run(JBossThread.java:122)
                      

                       

                      I can't really say why it ended up this way, since it requires knowledge about what exactly the application code looks like. Having said that, if this is being run in a production environment, I would disable console appender and that might get you past this problem. You can remove logging to console by getting rid of:

                       

                      <handler name="CONSOLE"/>
                      

                       

                      from the logging subsystem, from the relevant standalone/domain configuration XML. Or if you have some kind of log4j.xml/log4j.properties which uses ConsoleAppender, you might have to disable that one too.

                       

                      These are just workarounds. Someone with more knowledge of these logging libraries might know of a real fix (either in your configuration or in the logging library implementations).

                      • 8. Re: Re: Re: Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
                        boaglio

                        Actually it was a strange log4j behavior of one of our custom components.

                         

                        Now it´s working fine, thank you for your help jaikiran ! 

                        • 9. Re: JBoss EAP 6.3.0 - strange behavior while deploying WAR files
                          sam.cackett

                          My project had exactly the same issue, we moved from JBOSS EAP 6.2 to 6.3 and suddenly we couldn't run more than one instance of our application any more without the whole of JBOSS crashing.

                           

                          After looking at thread dump and finding this forum, we found the issue to be with the log4j console appender. Removing this from the log4j.properties fixed the issue with JBOSS.

                           

                          Given that it worked fine on EAP 6.2 and not 6.3 - I'm not sure if the issue is a JBOSS or log4j one. I don't have time to look into it right now which means I probably never will know the root cause unfortunately.

                           

                          Either way, thank you and hope this helps someone else.