search

rabbitmq / workloads

Continuous validation of RabbitMQ workloads
Apache License 2.0
24 stars 15 forks source link

1d. not understanding expected behavior. #20

Open wlund-pivotal opened 4 years ago

wlund-pivotal commented 4 years ago

My cluster is running and I've run it a couple of times so I'm not positive what state i'm in. I've stopped both fire-and-forget and durableConsumer and then confirmed my cluster is up. Then I start DurableConsumer and I get this output:

2020-10-09 09:32:41.379 o.s.a.r.c.CachingConnectionFactory       Attempting to connect to: [localhost:5673, localhost:5674, localhost:5675]
2020-10-09 09:32:41.493 o.s.a.r.c.CachingConnectionFactory       Created new connection: durable-consumer#1/SimpleConnection@2d9dff65 [delegate=amqp://durable-consumer@127.0.0.1:5673/, localPort= 64474]
2020-10-09 09:32:41.577 o.s.c.s.b.BinderErrorChannel             Channel 'trades.trade-logger.errors' has 1 subscriber(s).
2020-10-09 09:32:41.578 o.s.c.s.b.BinderErrorChannel             Channel 'trades.trade-logger.errors' has 2 subscriber(s).
2020-10-09 09:32:41.609 o.s.i.a.i.AmqpInboundChannelAdapter      started bean 'inbound.trades.trade-logger'
2020-10-09 09:32:41.639 o.s.b.w.e.t.TomcatWebServer              Tomcat started on port(s): 8080 (http) with context path ''
2020-10-09 09:32:41.679 c.p.r.ResilientSpringRabbitmqApplication Started ResilientSpringRabbitmqApplication in 6.625 seconds (JVM running for 7.361)
2020-10-09 09:32:41.709 c.p.r.DurableTradeLogger                 Received Trade{ tradeId=3 accountId=1 asset=VMW amount=1000 buy=true timestamp=1602181622693} done
2020-10-09 09:32:42.719 c.p.r.c.FaultyConsumer                   Simulating failure. Attempts:1
2020-10-09 09:32:42.719 c.p.r.DurableTradeLogger                 Failed to processed trade 3 due to ChaosMoney on trade 3 after 1 attempts
2020-10-09 09:32:42.719 c.p.r.DurableTradeLogger                 Trade summary after trade 3: total received:1, missed:0, processed:0
2020-10-09 09:32:43.728 c.p.r.DurableTradeLogger                 Received Trade{ tradeId=3 accountId=1 asset=VMW amount=1000 buy=true timestamp=1602181622693} done
2020-10-09 09:32:44.732 c.p.r.c.FaultyConsumer                   Simulating failure. Attempts:2
2020-10-09 09:32:44.733 c.p.r.DurableTradeLogger                 Failed to processed trade 3 due to ChaosMoney on trade 3 after 2 attempts
2020-10-09 09:32:44.733 c.p.r.DurableTradeLogger                 Trade summary after trade 3: total received:2, missed:0, processed:0
2020-10-09 09:32:46.735 c.p.r.DurableTradeLogger                 Received Trade{ tradeId=3 accountId=1 asset=VMW amount=1000 buy=true timestamp=1602181622693} done
2020-10-09 09:32:47.737 c.p.r.c.FaultyConsumer                   Simulating failure. Attempts:3
2020-10-09 09:32:47.737 c.p.r.c.FaultyConsumer                   Simulating failure. Has exceeded maxTimes:2. next:nothing
2020-10-09 09:32:47.803 o.s.c.s.b.BindingService                 Trying to unbind 'durable-trade-logger-input', but no binding found.
2020-10-09 09:32:47.804 o.s.i.e.EventDrivenConsumer              Removing {logging-channel-adapter:_org.springframework.integration.errorLogger} as a subscriber to the 'errorChannel' channel
2020-10-09 09:32:47.804 o.s.i.c.PublishSubscribeChannel          Channel 'durable-consumer.errorChannel' has 0 subscriber(s).
2020-10-09 09:32:47.805 o.s.i.e.EventDrivenConsumer              stopped bean '_org.springframework.integration.errorLogger'
2020-10-09 09:32:47.809 o.s.a.r.l.SimpleMessageListenerContainer Waiting for workers to finish.
2020-10-09 09:32:52.814 o.s.a.r.l.SimpleMessageListenerContainer Workers not finished.
2020-10-09 09:32:52.815 o.s.a.r.l.SimpleMessageListenerContainer Closing channel for unresponsive consumer: Consumer@337bbfdf: tags=[[amq.ctag-pb7v2EMZBgSSHv_NaxETuQ]], channel=Cached Rabbit Channel: AMQChannel(amqp://durable-consumer@127.0.0.1:5673/,1), conn: Proxy@767191b1 Shared Rabbit Connection: null, acknowledgeMode=AUTO local queue size=0
2020-10-09 09:32:52.816 o.s.i.a.i.AmqpInboundChannelAdapter      stopped bean 'inbound.trades.trade-logger'
2020-10-09 09:32:52.818 o.s.c.s.b.BinderErrorChannel             Channel 'durable-consumer.trades.trade-logger.errors' has 1 subscriber(s).
2020-10-09 09:32:52.820 o.s.c.s.b.BinderErrorChannel             Channel 'durable-consumer.trades.trade-logger.errors' has 0 subscriber(s).
2020-10-09 09:32:52.822 o.s.s.c.ThreadPoolTaskScheduler          Shutting down ExecutorService 'taskScheduler'
2020-10-09 09:32:52.823 o.s.s.c.ThreadPoolTaskExecutor           Shutting down ExecutorService 'applicationTaskExecutor'

I was not expecting it to shutdown. I can see plenty of messages in ready state because I left it running last night but durable-consumer is failing.

So now I start fire-and-forget and then DurableConsumer after I see trades sent and I get:

2020-10-09 09:38:09.515 c.p.r.ResilientSpringRabbitmqApplication Started ResilientSpringRabbitmqApplication in 5.795 seconds (JVM running for 6.485)
2020-10-09 09:38:09.553 c.p.r.DurableTradeLogger                 Received Trade{ tradeId=3 accountId=1 asset=VMW amount=1000 buy=true timestamp=1602181622693} done
2020-10-09 09:38:10.562 c.p.r.c.FaultyConsumer                   Simulating failure. Attempts:1
2020-10-09 09:38:10.562 c.p.r.DurableTradeLogger                 Failed to processed trade 3 due to ChaosMoney on trade 3 after 1 attempts
2020-10-09 09:38:10.562 c.p.r.DurableTradeLogger                 Trade summary after trade 3: total received:1, missed:0, processed:0
2020-10-09 09:38:11.566 c.p.r.DurableTradeLogger                 Received Trade{ tradeId=3 accountId=1 asset=VMW amount=1000 buy=true timestamp=1602181622693} done
2020-10-09 09:38:12.566 c.p.r.c.FaultyConsumer                   Simulating failure. Attempts:2
2020-10-09 09:38:12.567 c.p.r.DurableTradeLogger                 Failed to processed trade 3 due to ChaosMoney on trade 3 after 2 attempts
2020-10-09 09:38:12.567 c.p.r.DurableTradeLogger                 Trade summary after trade 3: total received:2, missed:0, processed:0
2020-10-09 09:38:14.572 c.p.r.DurableTradeLogger                 Received Trade{ tradeId=3 accountId=1 asset=VMW amount=1000 buy=true timestamp=1602181622693} done
2020-10-09 09:38:15.574 c.p.r.c.FaultyConsumer                   Simulating failure. Attempts:3
2020-10-09 09:38:15.574 c.p.r.c.FaultyConsumer                   Simulating failure. Has exceeded maxTimes:2. next:nothing
2020-10-09 09:38:15.643 o.s.c.s.b.BindingService                 Trying to unbind 'durable-trade-logger-input', but no binding found.
2020-10-09 09:38:15.644 o.s.i.e.EventDrivenConsumer              Removing {logging-channel-adapter:_org.springframework.integration.errorLogger} as a subscriber to the 'errorChannel' channel
2020-10-09 09:38:15.644 o.s.i.c.PublishSubscribeChannel          Channel 'durable-consumer.errorChannel' has 0 subscriber(s).
2020-10-09 09:38:15.644 o.s.i.e.EventDrivenConsumer              stopped bean '_org.springframework.integration.errorLogger'
2020-10-09 09:38:15.647 o.s.s.c.ThreadPoolTaskScheduler          Shutting down ExecutorService 'taskScheduler'
2020-10-09 09:38:15.649 o.s.a.r.l.SimpleMessageListenerContainer Waiting for workers to finish.
2020-10-09 09:38:20.651 o.s.a.r.l.SimpleMessageListenerContainer Workers not finished.
2020-10-09 09:38:20.652 o.s.a.r.l.SimpleMessageListenerContainer Closing channel for unresponsive consumer: Consumer@7baf1f5a: tags=[[amq.ctag-jNSCx9cM3UQ-sR7DkUigtQ]], channel=Cached Rabbit Channel: AMQChannel(amqp://durable-consumer@127.0.0.1:5673/,1), conn: Proxy@6b2e46af Shared Rabbit Connection: SimpleConnection@65bdd558 [delegate=amqp://durable-consumer@127.0.0.1:5673/, localPort= 64598], acknowledgeMode=AUTO local queue size=0
2020-10-09 09:38:20.660 o.s.i.a.i.AmqpInboundChannelAdapter      stopped bean 'inbound.trades.trade-logger'
2020-10-09 09:38:20.668 o.s.c.s.DefaultLifecycleProcessor        Failed to stop bean 'inputBindingLifecycle'
org.springframework.beans.factory.BeanCreationNotAllowedException: Error creating bean with name 'trades.trade-logger.errors.bridge': Singleton bean creation not allowed while singletons of this factory are in destruction (Do not request a bean from a BeanFactory in a destroy method implementation!)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:220)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:322)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:207)
    at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1115)
    at org.springframework.cloud.stream.binder.AbstractMessageChannelBinder.destroyErrorInfrastructure(AbstractMessageChannelBinder.java:789)
    at org.springframework.cloud.stream.binder.AbstractMessageChannelBinder.access$300(AbstractMessageChannelBinder.java:90)
    at org.springframework.cloud.stream.binder.AbstractMessageChannelBinder$2.afterUnbind(AbstractMessageChannelBinder.java:443)
    at org.springframework.cloud.stream.binder.DefaultBinding.unbind(DefaultBinding.java:168)
    at org.springframework.cloud.stream.binding.BindingService.unbindConsumers(BindingService.java:351)
    at org.springframework.cloud.stream.binding.AbstractBindableProxyFactory.unbindInputs(AbstractBindableProxyFactory.java:156)
    at org.springframework.cloud.stream.binding.InputBindingLifecycle.doStopWithBindable(InputBindingLifecycle.java:66)
    at java.base/java.util.LinkedHashMap$LinkedValues.forEach(LinkedHashMap.java:608)
    at org.springframework.cloud.stream.binding.AbstractBindingLifecycle.stop(AbstractBindingLifecycle.java:68)
    at org.springframework.cloud.stream.binding.InputBindingLifecycle.stop(InputBindingLifecycle.java:34)
    at org.springframework.cloud.stream.binding.AbstractBindingLifecycle.stop(AbstractBindingLifecycle.java:85)
    at org.springframework.cloud.stream.binding.InputBindingLifecycle.stop(InputBindingLifecycle.java:34)
    at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:238)
    at org.springframework.context.support.DefaultLifecycleProcessor.access$300(DefaultLifecycleProcessor.java:53)
    at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:377)
    at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:210)
    at org.springframework.context.support.DefaultLifecycleProcessor.stop(DefaultLifecycleProcessor.java:116)
    at org.springframework.context.support.AbstractApplicationContext.stop(AbstractApplicationContext.java:1370)
    at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:251)
    at org.springframework.context.support.DefaultLifecycleProcessor.access$300(DefaultLifecycleProcessor.java:53)
    at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:377)
    at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:210)
    at org.springframework.context.support.DefaultLifecycleProcessor.onClose(DefaultLifecycleProcessor.java:128)
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1022)
    at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:949)
2020-10-09 09:38:50.672 o.s.c.s.DefaultLifecycleProcessor        Failed to shut down 1 bean with phase value 2147482647 within timeout of 30000ms: [inputBindingLifecycle]
2020-10-09 09:38:50.685 o.s.s.c.ThreadPoolTaskExecutor           Shutting down ExecutorService 'applicationTaskExecutor'

What is the expected behavior? Screen Shot 2020-10-09 at 9 46 44 AM

MarcialRosales commented 4 years ago

@wlund-pivotal is this still an issue?