JBossDeveloper

I also put a test, much worse (in terms of load) than yours probably, as I was just generating messages ramdonly for a whole weekend.. stopping and starting the server.. and I didn't see this issue.

Thanks for your help on finding and fixing the issue.

Unfortunately, I have seen a couple more IllegalStateException(s).  The stacktraces are below.

The first occurred after we had an event on the machine that caused JBoss to be killed.  The second was after a clean shutdown.

==========

2010-06-10 09:32:37,063 ERROR [org.jboss.kernel.plugins.dependency.AbstractKernelController] (main) Error installing to Start: name=JMSServerManager state=Create

java.lang.IllegalStateException: Cannot find message 1881610

    at org.hornetq.core.persistence.impl.journal.JournalStorageManager.loadMessageJournal(JournalStorageManager.java:923)

    at org.hornetq.core.server.impl.HornetQServerImpl.loadJournals(HornetQServerImpl.java:1206)

    at org.hornetq.core.server.impl.HornetQServerImpl.initialisePart2(HornetQServerImpl.java:1056)

    at org.hornetq.core.server.impl.HornetQServerImpl.start(HornetQServerImpl.java:310)

    at org.hornetq.jms.server.impl.JMSServerManagerImpl.start(JMSServerManagerImpl.java:235)

    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 org.jboss.reflect.plugins.introspection.ReflectionUtils.invoke(ReflectionUtils.java:59)

    at org.jboss.reflect.plugins.introspection.ReflectMethodInfoImpl.invoke(ReflectMethodInfoImpl.java:150)

    at org.jboss.joinpoint.plugins.BasicMethodJoinPoint.dispatch(BasicMethodJoinPoint.java:66)

    at org.jboss.kernel.plugins.dependency.KernelControllerContextAction$JoinpointDispatchWrapper.execute(KernelControllerContextAction.java:241)

    at org.jboss.kernel.plugins.dependency.ExecutionWrapper.execute(ExecutionWrapper.java:47)

    at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchExecutionWrapper(KernelControllerContextAction.java:109)

    at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchJoinPoint(KernelControllerContextAction.java:70)

    at org.jboss.kernel.plugins.dependency.LifecycleAction.installActionInternal(LifecycleAction.java:221)

    at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54)

    at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42)

    at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62)

    at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71)

    at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51)

    at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)

    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)

    at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)

    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)

    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)

    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:774)

    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:540)

    at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.deploy(BeanMetaDataDeployer.java:121)

    at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.deploy(BeanMetaDataDeployer.java:51)

    at org.jboss.deployers.spi.deployer.helpers.AbstractSimpleRealDeployer.internalDeploy(AbstractSimpleRealDeployer.java:62)

    at org.jboss.deployers.spi.deployer.helpers.AbstractRealDeployer.deploy(AbstractRealDeployer.java:50)

    at org.jboss.deployers.plugins.deployers.DeployerWrapper.deploy(DeployerWrapper.java:171)

    at org.jboss.deployers.plugins.deployers.DeployersImpl.doDeploy(DeployersImpl.java:1439)

    at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1157)

    at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1178)

    at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1210)

    at org.jboss.deployers.plugins.deployers.DeployersImpl.install(DeployersImpl.java:1098)

    at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)

    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)

    at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)

    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)

    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)

    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)

    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)

    at org.jboss.deployers.plugins.deployers.DeployersImpl.process(DeployersImpl.java:781)

    at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:702)

    at org.jboss.system.server.profileservice.repository.MainDeployerAdapter.process(MainDeployerAdapter.java:117)

    at org.jboss.system.server.profileservice.repository.ProfileDeployAction.install(ProfileDeployAction.java:70)

    at org.jboss.system.server.profileservice.repository.AbstractProfileAction.install(AbstractProfileAction.java:53)

    at org.jboss.system.server.profileservice.repository.AbstractProfileService.install(AbstractProfileService.java:361)

    at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)

    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)

    at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)

    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)

    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)

    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)

    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)

    at org.jboss.system.server.profileservice.repository.AbstractProfileService.activateProfile(AbstractProfileService.java:306)

    at org.jboss.system.server.profileservice.ProfileServiceBootstrap.start(ProfileServiceBootstrap.java:271)

    at org.jboss.bootstrap.AbstractServerImpl.start(AbstractServerImpl.java:461)

    at org.jboss.Main.boot(Main.java:221)

    at org.jboss.Main$1.run(Main.java:556)

    at java.lang.Thread.run(Thread.java:619)

==========

==========

2010-06-11 18:04:18,278 ERROR [org.jboss.kernel.plugins.dependency.AbstractKernelController] (main) Error installing to Start: name=JMSServerManager state=Create
java.lang.IllegalStateException: Cannot find message 2147487475
    at org.hornetq.core.persistence.impl.journal.JournalStorageManager.loadMessageJournal(JournalStorageManager.java:857)
    at org.hornetq.core.server.impl.HornetQServerImpl.loadJournals(HornetQServerImpl.java:1206)
    at org.hornetq.core.server.impl.HornetQServerImpl.initialisePart2(HornetQServerImpl.java:1056)
    at org.hornetq.core.server.impl.HornetQServerImpl.start(HornetQServerImpl.java:310)
    at org.hornetq.jms.server.impl.JMSServerManagerImpl.start(JMSServerManagerImpl.java:235)
    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 org.jboss.reflect.plugins.introspection.ReflectionUtils.invoke(ReflectionUtils.java:59)
    at org.jboss.reflect.plugins.introspection.ReflectMethodInfoImpl.invoke(ReflectMethodInfoImpl.java:150)
    at org.jboss.joinpoint.plugins.BasicMethodJoinPoint.dispatch(BasicMethodJoinPoint.java:66)
    at org.jboss.kernel.plugins.dependency.KernelControllerContextAction$JoinpointDispatchWrapper.execute(KernelControllerContextAction.java:241)
    at org.jboss.kernel.plugins.dependency.ExecutionWrapper.execute(ExecutionWrapper.java:47)
    at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchExecutionWrapper(KernelControllerContextAction.java:109)
    at org.jboss.kernel.plugins.dependency.KernelControllerContextAction.dispatchJoinPoint(KernelControllerContextAction.java:70)
    at org.jboss.kernel.plugins.dependency.LifecycleAction.installActionInternal(LifecycleAction.java:221)
    at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:54)
    at org.jboss.kernel.plugins.dependency.InstallsAwareAction.installAction(InstallsAwareAction.java:42)
    at org.jboss.dependency.plugins.action.SimpleControllerContextAction.simpleInstallAction(SimpleControllerContextAction.java:62)
    at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:71)
    at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51)
    at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)
    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)
    at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)
    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:774)
    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:540)
    at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.deploy(BeanMetaDataDeployer.java:121)
    at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.deploy(BeanMetaDataDeployer.java:51)
    at org.jboss.deployers.spi.deployer.helpers.AbstractSimpleRealDeployer.internalDeploy(AbstractSimpleRealDeployer.java:62)
    at org.jboss.deployers.spi.deployer.helpers.AbstractRealDeployer.deploy(AbstractRealDeployer.java:50)
    at org.jboss.deployers.plugins.deployers.DeployerWrapper.deploy(DeployerWrapper.java:171)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.doDeploy(DeployersImpl.java:1439)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1157)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1178)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1210)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.install(DeployersImpl.java:1098)
    at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)
    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)
    at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)
    at org.jboss.deployers.plugins.deployers.DeployersImpl.process(DeployersImpl.java:781)
    at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:702)
    at org.jboss.system.server.profileservice.repository.MainDeployerAdapter.process(MainDeployerAdapter.java:117)
    at org.jboss.system.server.profileservice.repository.ProfileDeployAction.install(ProfileDeployAction.java:70)
    at org.jboss.system.server.profileservice.repository.AbstractProfileAction.install(AbstractProfileAction.java:53)
    at org.jboss.system.server.profileservice.repository.AbstractProfileService.install(AbstractProfileService.java:361)
    at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)
    at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)
    at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)
    at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)
    at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)
    at org.jboss.system.server.profileservice.repository.AbstractProfileService.activateProfile(AbstractProfileService.java:306)
    at org.jboss.system.server.profileservice.ProfileServiceBootstrap.start(ProfileServiceBootstrap.java:271)
    at org.jboss.bootstrap.AbstractServerImpl.start(AbstractServerImpl.java:461)
    at org.jboss.Main.boot(Main.java:221)
    at org.jboss.Main$1.run(Main.java:556)
    at java.lang.Thread.run(Thread.java:619)

==========

did you change any of the sync options on the journal?

Also, did you see any messages during the clean shutdown?

None of the journal sync options were touched, though we are now running with persist-delivery-count-before-delivery set to true.

I did not see anything out of the ordinary on shutdown.  I'm trying to recreate it again to see if there is anything I missed.

Under what conditions would you expect to see this error?

Two situations:

- If you disabled syncs on the Journal... you could have the message being received before the write was finished on the journal, and the ACK being written. which is not your case now.

- I saw this happening once on a test: https://jira.jboss.org/browse/HORNETQ-407

  And I had to add a changes on the shutdown code.

  When this happened on my case it would be safe to ignore the failures. (I mean.. to change the code to ignore the failures).

I then put the system to work for 72 hours straight shutting down and starting up and I couldn't replicate it any more.

David Hawes wrote:

 

None of the journal sync options were touched, though we are now running with persist-delivery-count-before-delivery set to true.

 

I did not see anything out of the ordinary on shutdown.  I'm trying to recreate it again to see if there is anything I missed.

 

Under what conditions would you expect to see this error?

If you could create a simple test program that roughly simulates your workload - e.g. create some consumers, producers, send messages, consume messages, along with config, this would be a great help in reproducing this issue.

I typically push somewhere around 300,000 messages through before I start shutting down.  I wish I had a test that reliably caused this issue, but it's still quite sporadic.  I thought I noticed a higher rate of IllegalStateExceptions when I bumped the journal-compact-percentage to 60, but that observation doesn't seem to be holding up.

It seems desirable to at least recover from this state somehow.  If I have thousands of messages sitting around and only a small number are causing the issue, I'd much rather just lose those messages.  Losing some is better than all, at least for our setup.

I don't think you would lose any messages. I saw that exception happening on test once when shutting down while the compactor was on.  And that was fixed on trunk (or 2.1.1).

When it happened, all of those messages were previously consumed while compacting was happening during the shutdown.

Can you change the code to ignore warnings? (log.warn instead of throw new Exception). That would do it for you.

I will add an option on the Storagemanager to ignore failures on load.

We always try to avoid having failures.. but in case they happen we need to know to take actions, and eventually ignore them.

When I last evaluated this case, it would be safe to ignore those messages.

Message was edited by: Clebert Suconic

I don't have any more information, but I do still notice the IllegalStateException(s) with 2.1.1.

Same error:

I use ubuntu 10.04 server, java 1.6.0_20, filesystem ext4 and hornetq 2.1.1-final stand-alone

The sequence of operations was:

1) stop hornetq

2) edit configuration files (add user and its permission) but with a error (missed close tags in hornetq-configuration.xml)

3) start hornetq with error (obviously)

4) stop hornetq but i can see any message and after 10 minutes the java process was up too

5) kill java process and now i see stopping hornetq....

6) edit configuration and correct the file

7) start hornetq with error

***********************************************************************************
[main] 18:31:20,807 INFO [org.hornetq.integration.bootstrap.HornetQBootstrapServer]  Starting HornetQ Server
[main] 18:31:21,534 INFO [org.hornetq.core.server.impl.HornetQServerImpl]  live server is starting..
[main] 18:31:21,556 INFO [org.hornetq.core.persistence.impl.journal.JournalStorageManager]  Using AIO Journal
[main] 18:31:21,566 WARNING [org.hornetq.core.server.impl.HornetQServerImpl]  Security risk! It has been detected that the cluster admin user and password have not been changed from the installation default. Please see the HornetQ user guide, cluster chapter, for instructions on how to do this.
[main] 18:31:30,898 SEVERE [org.hornetq.integration.bootstrap.HornetQBootstrapServer]  Failed to start server
java.lang.IllegalStateException: Incompletely deployed:

DEPLOYMENTS IN ERROR:
   Deployment "JMSServerManager" is in error due to: java.lang.IllegalStateException: Cannot find message 154916

    at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.internalValidate(AbstractKernelDeployer.java:278)
     at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.validate(AbstractKernelDeployer.java:174)
     at org.hornetq.integration.bootstrap.HornetQBootstrapServer.bootstrap(HornetQBootstrapServer.java:158)
     at org.jboss.kernel.plugins.bootstrap.AbstractBootstrap.run(AbstractBootstrap.java:83)
     at org.hornetq.integration.bootstrap.HornetQBootstrapServer.run(HornetQBootstrapServer.java:116)
     at org.hornetq.integration.bootstrap.HornetQBootstrapServer.main(HornetQBootstrapServer.java:73)
Exception in thread "main" java.lang.IllegalStateException: Incompletely deployed:

DEPLOYMENTS IN ERROR:
   Deployment "JMSServerManager" is in error due to: java.lang.IllegalStateException: Cannot find message 154916

    at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.internalValidate(AbstractKernelDeployer.java:278)
     at org.jboss.kernel.plugins.deployment.AbstractKernelDeployer.validate(AbstractKernelDeployer.java:174)
     at org.hornetq.integration.bootstrap.HornetQBootstrapServer.bootstrap(HornetQBootstrapServer.java:158)
     at org.jboss.kernel.plugins.bootstrap.AbstractBootstrap.run(AbstractBootstrap.java:83)
     at org.hornetq.integration.bootstrap.HornetQBootstrapServer.run(HornetQBootstrapServer.java:116)
     at org.hornetq.integration.bootstrap.HornetQBootstrapServer.main(HornetQBootstrapServer.java:73)

Are you sending any messages on the process of generating an error?

Server is in a production environment, there are about ten client.

I'm not sure by it is probably that same client was sending or receiving messages during shutdown/restart.