8 Replies Latest reply on Nov 20, 2009 10:16 AM by sintetik7

    TimerService Restart Issue

    dolsen

      I have the following Timer service class defined:

      @Stateless
      @RemoteBinding(jndiBinding="XXXCommandRemote")
      public class XXXCommandBean implements XXXCommandRemote
      {
       static Logger logger = Logger.getLogger(XXXCommandBean.class);
      
       @Resource TimerService timerService;
      
       public void scheduleCommand(Command command)
       {
       timerService.createTimer(command.getDuration(), command);
       }
      
       public void scheduleContinousCommand(Command command)
       {
       timerService.createTimer(command.getDuration(), command.getDuration(), command);
       }
      
       @Timeout
       public void runCommand(Timer timer)
       {
       Command command = (Command) timer.getInfo();
      
       logger.debug("runCommand: Firing command for user: " + command.getUserId() + " " + command.getDescription());
      
       User user = null;
      
       System.setProperty("java.security.policy", "server.policy");
       if (System.getSecurityManager() == null)
       {
       System.setSecurityManager(new RMISecurityManager());
       }
      
       InitialContext jndiContext;
       try
       {
       jndiContext = getInitialContext();
       UserRemote playerRef = (UserRemote) jndiContext.lookup("UserRemote");
       USerRemote dao = (UserRemote) PortableRemoteObject.narrow(playerRef, UserRemote.class);
       user = dao.findUser(command.getUserId());
       }
       catch (NamingException e)
       {
       logger.error("NamingException: ", e);
       }
      ...
      


      This seems to work fine in normal cases.

      However, if I have a command scheduled for the future, and then restart the app server I get the following error when the Timeout hook runs:

      2009-02-19 08:31:04,125 DEBUG [org.jboss.ejb3.proxy.objectfactory.session.SessionProxyObjectFactory] (EJB-Timer-1235057250689[target=jboss.j2ee:ear=feudalism.ear,jar=feudalism
      -beans.jar,name=XXXCommandBean,service=EJB3]) Created Proxy of type $Proxy140 for EJB3 Business Interface: com.feudalism.session.user.UserRemote
      2009-02-19 08:31:04,125 ERROR [com.feudalism.session.user.UserBean] (EJB-Timer-1235057250689[target=jboss.j2ee:ear=feudalism.ear,jar=feudalism-beans.jar,name=XXXCommandBean,service=EJB3]) NamingException:
      javax.naming.NamingException: Could not dereference object [Root exception is java.lang.RuntimeException: Can not find interface declared by Proxy in our CL + BaseClassLoader@
      13c72d{vfsfile:/C:/java/jboss-5.0.0.GA/jboss-5.0.0.GA/server/feudalism/deploy/ejb2-timer-service.xml}]
       at org.jnp.interfaces.NamingContext.getObjectInstanceWrapFailure(NamingContext.java:1463)
       at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:809)
       at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:673)
       at javax.naming.InitialContext.lookup(InitialContext.java:351)
       at com.feudalism.session.command.XXXCommandBean.runCommand(XXXCommandBean.java:92)
      


      This is happening during lookup:
      UserRemote playerRef = (UserRemote)jndiContext.lookup("UserRemote");

        • 1. Re: TimerService Restart Issue
          jaikiran

          I think i understand what's happening. When the app servers starts, its triggering the jobs using a classloader which is not the one expected for your application. Can you please post the entire console logs and the entire exception stacktrace when you restart the server? Also if possible could you please enable the TRACE level logging of org.jboss.classloading and upload that log file to some accessible place (i would not recommend posting the logs here since its going to be too long). Here's how you can enable TRACE logging and redirect it to a specific file:

          <appender name="CL_LOGS" class="org.jboss.logging.appender.RollingFileAppender">
           <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
           <param name="File" value="${jboss.server.log.dir}/cl.log"/>
           <param name="Append" value="false"/>
           <param name="MaxFileSize" value="5000KB"/>
           <param name="MaxBackupIndex" value="10"/>
           <param name="Threshold" value="TRACE"/>
          
           <layout class="org.apache.log4j.PatternLayout">
           <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>
           </layout>
           </appender>
          
           ... //later in the file
          
          
           <category name="org.jboss.classloading">
           <priority value="TRACE" />
           <appender-ref ref="CL_LOGS"/>
           </category>


          You can add this piece to the jboss-log4j.xml in the %JBOSS_HOME%/server/feudalism/conf folder.

          • 2. Re: TimerService Restart Issue
            dolsen

            I will add more logs tomorrow.

            I have rewritten the timer user EJB injection and get slightly different errors, but it might shed some more light on the problem.

            It definitely looks like a class loader issue though...

            I have also seen the following exception:

            2009-02-21 21:31:36,562 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1235187861590[target=jboss.j2ee:ear=feudalism.ear,jar=feudalism-beans.jar,name=CommandEJB,service=EJ
            B3]) setTimerState: in_timeout
            2009-02-21 21:31:36,562 ERROR [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1235187861590[target=jboss.j2ee:ear=feudalism.ear,jar=feudalism-beans.jar,name=CommandEJB,service=EJ
            B3]) Error invoking ejbTimeout
            org.jboss.aop.DispatcherConnectException: EJB container is not completely started, or is stopped.
             at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:60)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
             at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
             at org.jboss.ejb3.stateless.StatelessContainer.callTimeout(StatelessContainer.java:304)
             at org.jboss.ejb.txtimer.TimerImpl$TimerTaskImpl.run(TimerImpl.java:561)
             at java.util.TimerThread.mainLoop(Timer.java:512)
             at java.util.TimerThread.run(Timer.java:462)
            2009-02-21 21:31:36,562 DEBUG [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-1235187861590[target=jboss.j2ee:ear=feudalism.ear,jar=feudalism-beans.jar,name=CommandEJB,service=EJ
            B3]) Timer was not registered with Tx, resetting state: [id=1235187861590,target=[target=jboss.j2ee:ear=feudalism.ear,jar=feudalism-beans.jar,name=CommandEJB,service=EJB3],rem
            aining=-23110031,periode=3600000,in_timeout]
            


            After I restart the server and if there are no expired timers but timers in the future, when the timeout happens I get:

            2009-02-24 20:35:15,406 ERROR [org.jboss.ejb.txtimer.TimerImpl] (EJB-Timer-12355
            32907815[target=jboss.j2ee:ear=feudalism.ear,jar=feudalism-beans.jar,name=Comman
            dEJB,service=EJB3]) Error invoking ejbTimeout
            javax.ejb.EJBException: java.lang.RuntimeException: Unable to inject jndi depend
            ency: env/com.feudalism.session.command.XXXCommandBean/playerBean into property
            com.feudalism.session.command.XXXCommandBean.playerBean: com.feudalism.session.p
            layer.PlayerRemote from BaseClassLoader@10ed791{VFSClassLoaderPolicy@16aa365{nam
            e=vfsfile:/C:/java/jboss-5.0.0.GA/jboss-5.0.0.GA/server/feudalism/deploy/ejb2-ti
            mer-service.xml domain=ClassLoaderDomain@1dddba{name=DefaultDomain parentPolicy=
            BEFORE parent=org.jboss.system.NoAnnotationURLClassLoader@8a0d5d} roots=[MemoryC
            ontextHandler@880352[path= context=vfsmemory://5c4o01u-q581nz-frlgcin1-1-frlgdl0
            k-t real=vfsmemory://5c4o01u-q581nz-frlgcin1-1-frlgdl0k-t]] delegates=null expo
            rted=[] <IMPORT-ALL>NON_EMPTY}}
             at org.jboss.ejb3.tx.Ejb3TxPolicy.handleExceptionInOurTx(Ejb3TxPolicy.ja
            va:77)
             at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:83)
             at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java
            :190)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInt
            erceptor.java:76)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3Au
            thenticationInterceptorv2.java:75)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterce
            ptor.java:41)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(Asynchrono
            usInterceptor.java:106)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContaine
            rShutdownInterceptor.java:65)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invo
            ke(CurrentInvocationInterceptor.java:67)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.ejb3.stateless.StatelessContainer.callTimeout(StatelessCont
            ainer.java:304)
             at org.jboss.ejb.txtimer.TimerImpl$TimerTaskImpl.run(TimerImpl.java:561)
             at java.util.TimerThread.mainLoop(Timer.java:512)
             at java.util.TimerThread.run(Timer.java:462)
            Caused by: java.lang.RuntimeException: Unable to inject jndi dependency: env/com
            .feudalism.session.command.XXXCommandBean/playerBean into property com.feudalism
            .session.command.XXXCommandBean.playerBean: com.feudalism.session.player.PlayerR
            emote from BaseClassLoader@10ed791{VFSClassLoaderPolicy@16aa365{name=vfsfile:/C:
            /java/jboss-5.0.0.GA/jboss-5.0.0.GA/server/feudalism/deploy/ejb2-timer-service.x
            ml domain=ClassLoaderDomain@1dddba{name=DefaultDomain parentPolicy=BEFORE parent
            =org.jboss.system.NoAnnotationURLClassLoader@8a0d5d} roots=[MemoryContextHandler
            @880352[path= context=vfsmemory://5c4o01u-q581nz-frlgcin1-1-frlgdl0k-t real=vfsm
            emory://5c4o01u-q581nz-frlgcin1-1-frlgdl0k-t]] delegates=null exported=[] <IMPO
            RT-ALL>NON_EMPTY}}
             at org.jboss.injection.JndiPropertyInjector.lookup(JndiPropertyInjector.
            java:82)
             at org.jboss.injection.JndiPropertyInjector.inject(JndiPropertyInjector.
            java:99)
             at org.jboss.injection.JndiPropertyInjector.inject(JndiPropertyInjector.
            java:89)
             at org.jboss.injection.JndiPropertyInjector.inject(JndiPropertyInjector.
            java:61)
             at org.jboss.ejb3.injection.InjectionInvocation.invokeTarget(InjectionIn
            vocation.java:89)
             at org.jboss.ejb3.injection.InjectionInvocation.invokeNext(InjectionInvo
            cation.java:83)
             at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invo
            ke(CurrentInvocationInterceptor.java:67)
             at org.jboss.ejb3.injection.InjectionInvocation.invokeNext(InjectionInvo
            cation.java:74)
             at org.jboss.ejb3.EJBContainer.injectBeanContext(EJBContainer.java:1076)
             at org.jboss.ejb3.pool.AbstractPool.create(AbstractPool.java:83)
             at org.jboss.ejb3.InfinitePool.get(InfinitePool.java:56)
             at org.jboss.ejb3.InfinitePool.get(InfinitePool.java:51)
             at org.jboss.ejb3.pool.ThreadlocalPool.create(ThreadlocalPool.java:53)
             at org.jboss.ejb3.pool.ThreadlocalPool.get(ThreadlocalPool.java:93)
             at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(Stateles
            sInstanceInterceptor.java:58)
             at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.
            java:102)
             at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
             ... 20 more
            Caused by: javax.naming.NamingException: Could not dereference object [Root exce
            ption is javax.naming.NamingException: Could not dereference object [Root except
            ion is java.lang.RuntimeException: Can not find interface declared by Proxy in o
            ur CL + BaseClassLoader@10ed791{vfsfile:/C:/java/jboss-5.0.0.GA/jboss-5.0.0.GA/s
            erver/feudalism/deploy/ejb2-timer-service.xml}]]
             at org.jnp.interfaces.NamingContext.resolveLink(NamingContext.java:1339)
             at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:804)
             at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:673)
             at org.jboss.ejb3.JndiUtil.lookup(JndiUtil.java:44)
             at org.jboss.injection.JndiPropertyInjector.lookup(JndiPropertyInjector.
            java:75)
             ... 36 more
            Caused by: javax.naming.NamingException: Could not dereference object [Root exce
            ption is java.lang.RuntimeException: Can not find interface declared by Proxy in
             our CL + BaseClassLoader@10ed791{vfsfile:/C:/java/jboss-5.0.0.GA/jboss-5.0.0.GA
            /server/feudalism/deploy/ejb2-timer-service.xml}]
             at org.jnp.interfaces.NamingContext.getObjectInstanceWrapFailure(NamingC
            ontext.java:1463)
             at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:809)
             at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:673)
             at javax.naming.InitialContext.lookup(InitialContext.java:351)
             at org.jnp.interfaces.NamingContext.resolveLink(NamingContext.java:1333)
             ... 40 more
            Caused by: java.lang.RuntimeException: Can not find interface declared by Proxy
            in our CL + BaseClassLoader@10ed791{vfsfile:/C:/java/jboss-5.0.0.GA/jboss-5.0.0.
            GA/server/feudalism/deploy/ejb2-timer-service.xml}
             at org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory.redefineProxyIn
            Tcl(ProxyObjectFactory.java:341)
             at org.jboss.ejb3.proxy.objectfactory.session.SessionProxyObjectFactory.
            createProxy(SessionProxyObjectFactory.java:134)
             at org.jboss.ejb3.proxy.objectfactory.session.stateless.StatelessSession
            ProxyObjectFactory.getProxy(StatelessSessionProxyObjectFactory.java:79)
             at org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory.getObjectInstan
            ce(ProxyObjectFactory.java:156)
             at javax.naming.spi.NamingManager.getObjectInstance(NamingManager.java:3
            04)
             at org.jnp.interfaces.NamingContext.getObjectInstance(NamingContext.java
            :1438)
             at org.jnp.interfaces.NamingContext.getObjectInstanceWrapFailure(NamingC
            ontext.java:1455)
             ... 44 more
            Caused by: java.lang.ClassNotFoundException: com.feudalism.session.player.Player
            Remote from BaseClassLoader@10ed791{VFSClassLoaderPolicy@16aa365{name=vfsfile:/C
            :/java/jboss-5.0.0.GA/jboss-5.0.0.GA/server/feudalism/deploy/ejb2-timer-service.
            xml domain=ClassLoaderDomain@1dddba{name=DefaultDomain parentPolicy=BEFORE paren
            t=org.jboss.system.NoAnnotationURLClassLoader@8a0d5d} roots=[MemoryContextHandle
            r@880352[path= context=vfsmemory://5c4o01u-q581nz-frlgcin1-1-frlgdl0k-t real=vfs
            memory://5c4o01u-q581nz-frlgcin1-1-frlgdl0k-t]] delegates=null exported=[] <IMP
            ORT-ALL>NON_EMPTY}}
             at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoa
            der.java:385)
             at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
             at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
             at java.lang.Class.forName0(Native Method)
             at java.lang.Class.forName(Class.java:242)
             at org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory.redefineProxyIn
            Tcl(ProxyObjectFactory.java:337)
             ... 50 more
            


            • 3. Re: TimerService Restart Issue
              kyle.bober

              I am running into the same issue. Were you able to resolve or figure out how to work around this issue?

              • 4. Re: TimerService Restart Issue
                rodedh

                I get this exception as well. Is there any issue with dependency injection in EJBs when ejbtimeout is invoked?

                Thanks,
                Rod

                • 5. Re: TimerService Restart Issue
                  jaikiran

                   

                  I get this exception as well. Is there any issue with dependency injection in EJBs when ejbtimeout is invoked?

                  Thanks,
                  Rod


                  Which exact error? Please post the entire exception stacktrace.

                  There are 2 exceptions mentioned in this thread:

                  1)

                  javax.naming.NamingException: Could not dereference object [Root exception is java.lang.RuntimeExcep
                  tion: Can not find interface declared by Proxy in our CL + BaseClassLoader@
                  13c72d{vfsfile:/C:/java/jboss-5.0.0.GA/jboss-5.0.0.GA/server/feudalism/deploy/ejb2-timer-service.xml
                  }]
                  


                  2)

                  org.jboss.aop.DispatcherConnectException: EJB container is not completely started, or is stopped.
                   at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor
                  .java:60)
                  


                  If it's the second error that you are running into, then watch this JIRA https://jira.jboss.org/jira/browse/EJBTHREE-1926


                  While posting logs or xml content or code, please remember to wrap it in a code block by using the Code button in the message editor window. Please use the Preview button to ensure that your post is correctly formatted.



                  • 6. Re: TimerService Restart Issue
                    sintetik7

                    I've just had a similar issue with Timer and EJB injection, at application redeploy / server restart. Direct JNDI lookup didn't work out as well.

                    What I did is a partial workaround - I switched to timer start thru MBean in sar module and I do reset all the timers in MBean stop() method.

                    This way I don't get any perstent timers kept but there's no any classloader / "Could not dereference object" errors at new timers creation.

                    • 7. Re: TimerService Restart Issue
                      jaikiran

                      Try our latest EJB3 plugin http://www.jboss.org/ejb3/ejb3plugin.html against AS-5.1.0.

                      The latest download is available here http://www.jboss.org/ejb3/downloads.html

                      If the latest plugin too doesn't solve your issue then please post the entire details.

                      • 8. Re: TimerService Restart Issue
                        sintetik7

                         

                        "jaikiran" wrote:
                        Try our latest EJB3 plugin http://www.jboss.org/ejb3/ejb3plugin.html against AS-5.1.0.



                        Thanks for suggestion, i've tried JBoss EJB3 Plugin 1.0.18 (JBoss 5.1).

                        I didn't reproduce all the code I had before but the problem ("Could not dereference object") doesn't appear anymore, at least if i do NOT cancel timers at application shutown.